[==========] 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:16:38.452726  7841 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.7.168.126:46837
I20260812 06:16:38.453636  7841 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:16:38.454154  7841 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:38.460134  7853 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:16:38.460233  7841 server_base.cc:1061] running on GCE node
W20260812 06:16:38.460153  7857 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:16:38.460435  7849 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:38.460983  7841 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:38.461074  7841 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:16:38.461104  7841 hybrid_clock.cc:648] HybridClock initialized: now 1786515398461103 us; error 0 us; skew 500 ppm
I20260812 06:16:38.462787  7841 webserver.cc:533] Webserver started at http://127.7.168.126:38797/ using document root <none> and password file <none>
I20260812 06:16:38.463271  7841 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:38.463327  7841 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:38.463536  7841 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:38.465183  7841 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398442455-7841-0/minicluster-data/master-0-root/instance:
uuid: "3991fc5573a84538822721d95c2b17b4"
format_stamp: "Formatted at 2026-08-12 06:16:38 on dist-test-slave-45dx"
I20260812 06:16:38.468905  7841 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.004s	sys 0.000s
I20260812 06:16:38.470808  7866 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:16:38.471757  7841 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:16:38.471879  7841 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398442455-7841-0/minicluster-data/master-0-root
uuid: "3991fc5573a84538822721d95c2b17b4"
format_stamp: "Formatted at 2026-08-12 06:16:38 on dist-test-slave-45dx"
I20260812 06:16:38.471972  7841 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398442455-7841-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398442455-7841-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398442455-7841-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:16:38.494796  7841 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:38.495455  7841 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:16:38.495648  7841 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:38.503260  7841 rpc_server.cc:307] RPC server started. Bound to: 127.7.168.126:46837
I20260812 06:16:38.503265  7961 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.7.168.126:46837 every 8 connection(s)
I20260812 06:16:38.505467  7963 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:16:38.510603  7963 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 3991fc5573a84538822721d95c2b17b4: Bootstrap starting.
I20260812 06:16:38.512895  7963 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 3991fc5573a84538822721d95c2b17b4: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:38.513777  7963 log.cc:826] T 00000000000000000000000000000000 P 3991fc5573a84538822721d95c2b17b4: Log is configured to *not* fsync() on all Append() calls
I20260812 06:16:38.515345  7963 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 3991fc5573a84538822721d95c2b17b4: No bootstrap required, opened a new log
I20260812 06:16:38.518041  7963 raft_consensus.cc:359] T 00000000000000000000000000000000 P 3991fc5573a84538822721d95c2b17b4 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3991fc5573a84538822721d95c2b17b4" member_type: VOTER }
I20260812 06:16:38.518200  7963 raft_consensus.cc:385] T 00000000000000000000000000000000 P 3991fc5573a84538822721d95c2b17b4 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:38.518241  7963 raft_consensus.cc:740] T 00000000000000000000000000000000 P 3991fc5573a84538822721d95c2b17b4 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 3991fc5573a84538822721d95c2b17b4, State: Initialized, Role: FOLLOWER
I20260812 06:16:38.518784  7963 consensus_queue.cc:260] T 00000000000000000000000000000000 P 3991fc5573a84538822721d95c2b17b4 [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: "3991fc5573a84538822721d95c2b17b4" member_type: VOTER }
I20260812 06:16:38.518956  7963 raft_consensus.cc:399] T 00000000000000000000000000000000 P 3991fc5573a84538822721d95c2b17b4 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:38.519032  7963 raft_consensus.cc:493] T 00000000000000000000000000000000 P 3991fc5573a84538822721d95c2b17b4 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:38.519201  7963 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 3991fc5573a84538822721d95c2b17b4 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:38.520040  7963 raft_consensus.cc:515] T 00000000000000000000000000000000 P 3991fc5573a84538822721d95c2b17b4 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3991fc5573a84538822721d95c2b17b4" member_type: VOTER }
I20260812 06:16:38.520494  7963 leader_election.cc:304] T 00000000000000000000000000000000 P 3991fc5573a84538822721d95c2b17b4 [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: 3991fc5573a84538822721d95c2b17b4; no voters: 
I20260812 06:16:38.520855  7963 leader_election.cc:290] T 00000000000000000000000000000000 P 3991fc5573a84538822721d95c2b17b4 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:38.520982  7967 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 3991fc5573a84538822721d95c2b17b4 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:38.521237  7967 raft_consensus.cc:697] T 00000000000000000000000000000000 P 3991fc5573a84538822721d95c2b17b4 [term 1 LEADER]: Becoming Leader. State: Replica: 3991fc5573a84538822721d95c2b17b4, State: Running, Role: LEADER
I20260812 06:16:38.521646  7967 consensus_queue.cc:237] T 00000000000000000000000000000000 P 3991fc5573a84538822721d95c2b17b4 [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: "3991fc5573a84538822721d95c2b17b4" member_type: VOTER }
I20260812 06:16:38.521863  7963 sys_catalog.cc:565] T 00000000000000000000000000000000 P 3991fc5573a84538822721d95c2b17b4 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:38.523584  7971 sys_catalog.cc:455] T 00000000000000000000000000000000 P 3991fc5573a84538822721d95c2b17b4 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "3991fc5573a84538822721d95c2b17b4" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3991fc5573a84538822721d95c2b17b4" member_type: VOTER } }
I20260812 06:16:38.523727  7971 sys_catalog.cc:458] T 00000000000000000000000000000000 P 3991fc5573a84538822721d95c2b17b4 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:38.523692  7973 sys_catalog.cc:455] T 00000000000000000000000000000000 P 3991fc5573a84538822721d95c2b17b4 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 3991fc5573a84538822721d95c2b17b4. Latest consensus state: current_term: 1 leader_uuid: "3991fc5573a84538822721d95c2b17b4" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3991fc5573a84538822721d95c2b17b4" member_type: VOTER } }
I20260812 06:16:38.523782  7973 sys_catalog.cc:458] T 00000000000000000000000000000000 P 3991fc5573a84538822721d95c2b17b4 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:38.524119  7983 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:38.526717  7983 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:38.526971  7841 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:38.531525  7983 catalog_manager.cc:1383] Generated new cluster ID: 8ee73728740b44bd99da98ec3ebabe42
I20260812 06:16:38.531599  7983 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:38.549922  7983 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:38.550769  7983 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:38.558485  7983 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 3991fc5573a84538822721d95c2b17b4: Generated new TSK 0
I20260812 06:16:38.559175  7983 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:38.591856  7841 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:38.594669  8014 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:16:38.594705  8010 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:16:38.594794  8006 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:38.594861  7841 server_base.cc:1061] running on GCE node
I20260812 06:16:38.595134  7841 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:38.595196  7841 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:16:38.595223  7841 hybrid_clock.cc:648] HybridClock initialized: now 1786515398595222 us; error 0 us; skew 500 ppm
I20260812 06:16:38.596199  7841 webserver.cc:533] Webserver started at http://127.7.168.65:33757/ using document root <none> and password file <none>
I20260812 06:16:38.596406  7841 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:38.596487  7841 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:38.596570  7841 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:38.596961  7841 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398442455-7841-0/minicluster-data/ts-0-root/instance:
uuid: "c029514ce665498cb57cc7b92168f537"
format_stamp: "Formatted at 2026-08-12 06:16:38 on dist-test-slave-45dx"
I20260812 06:16:38.598508  7841 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:16:38.599454  8023 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:16:38.599704  7841 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:38.599773  7841 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398442455-7841-0/minicluster-data/ts-0-root
uuid: "c029514ce665498cb57cc7b92168f537"
format_stamp: "Formatted at 2026-08-12 06:16:38 on dist-test-slave-45dx"
I20260812 06:16:38.599856  7841 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398442455-7841-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398442455-7841-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398442455-7841-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:16:38.610461  7841 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:38.610895  7841 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:38.611364  7841 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:38.612177  7841 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:38.612231  7841 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:38.612298  7841 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:38.612353  7841 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:38.619354  7841 rpc_server.cc:307] RPC server started. Bound to: 127.7.168.65:45337
I20260812 06:16:38.619402  8124 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.7.168.65:45337 every 8 connection(s)
I20260812 06:16:38.629657  8125 heartbeater.cc:344] Connected to a master server at 127.7.168.126:46837
I20260812 06:16:38.629884  8125 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:38.630299  8125 heartbeater.cc:507] Master 127.7.168.126:46837 requested a full tablet report, sending...
I20260812 06:16:38.631708  7891 ts_manager.cc:194] Registered new tserver with Master: c029514ce665498cb57cc7b92168f537 (127.7.168.65:45337)
I20260812 06:16:38.632238  7841 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012219473s
I20260812 06:16:38.633188  7891 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:50162
I20260812 06:16:38.642272  7891 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:50168:
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:16:38.656908  8064 tablet_service.cc:1511] Processing CreateTablet for tablet 4439eacba8dd4f8fbe8e75fa82936c6e (DEFAULT_TABLE table=heavy-update-compaction-test [id=0acedad6b96f4f18af534d525079a039]), partition=
I20260812 06:16:38.657397  8064 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 4439eacba8dd4f8fbe8e75fa82936c6e. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:38.659642  8152 tablet_bootstrap.cc:492] T 4439eacba8dd4f8fbe8e75fa82936c6e P c029514ce665498cb57cc7b92168f537: Bootstrap starting.
I20260812 06:16:38.660647  8152 tablet_bootstrap.cc:654] T 4439eacba8dd4f8fbe8e75fa82936c6e P c029514ce665498cb57cc7b92168f537: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:38.661903  8152 tablet_bootstrap.cc:492] T 4439eacba8dd4f8fbe8e75fa82936c6e P c029514ce665498cb57cc7b92168f537: No bootstrap required, opened a new log
I20260812 06:16:38.662027  8152 ts_tablet_manager.cc:1403] T 4439eacba8dd4f8fbe8e75fa82936c6e P c029514ce665498cb57cc7b92168f537: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:16:38.662446  8152 raft_consensus.cc:359] T 4439eacba8dd4f8fbe8e75fa82936c6e P c029514ce665498cb57cc7b92168f537 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c029514ce665498cb57cc7b92168f537" member_type: VOTER last_known_addr { host: "127.7.168.65" port: 45337 } }
I20260812 06:16:38.662568  8152 raft_consensus.cc:385] T 4439eacba8dd4f8fbe8e75fa82936c6e P c029514ce665498cb57cc7b92168f537 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:38.662616  8152 raft_consensus.cc:740] T 4439eacba8dd4f8fbe8e75fa82936c6e P c029514ce665498cb57cc7b92168f537 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: c029514ce665498cb57cc7b92168f537, State: Initialized, Role: FOLLOWER
I20260812 06:16:38.662752  8152 consensus_queue.cc:260] T 4439eacba8dd4f8fbe8e75fa82936c6e P c029514ce665498cb57cc7b92168f537 [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: "c029514ce665498cb57cc7b92168f537" member_type: VOTER last_known_addr { host: "127.7.168.65" port: 45337 } }
I20260812 06:16:38.662859  8152 raft_consensus.cc:399] T 4439eacba8dd4f8fbe8e75fa82936c6e P c029514ce665498cb57cc7b92168f537 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:38.662907  8152 raft_consensus.cc:493] T 4439eacba8dd4f8fbe8e75fa82936c6e P c029514ce665498cb57cc7b92168f537 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:38.662961  8152 raft_consensus.cc:3060] T 4439eacba8dd4f8fbe8e75fa82936c6e P c029514ce665498cb57cc7b92168f537 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:38.663689  8152 raft_consensus.cc:515] T 4439eacba8dd4f8fbe8e75fa82936c6e P c029514ce665498cb57cc7b92168f537 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c029514ce665498cb57cc7b92168f537" member_type: VOTER last_known_addr { host: "127.7.168.65" port: 45337 } }
I20260812 06:16:38.663847  8152 leader_election.cc:304] T 4439eacba8dd4f8fbe8e75fa82936c6e P c029514ce665498cb57cc7b92168f537 [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: c029514ce665498cb57cc7b92168f537; no voters: 
I20260812 06:16:38.664078  8152 leader_election.cc:290] T 4439eacba8dd4f8fbe8e75fa82936c6e P c029514ce665498cb57cc7b92168f537 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:38.664180  8157 raft_consensus.cc:2804] T 4439eacba8dd4f8fbe8e75fa82936c6e P c029514ce665498cb57cc7b92168f537 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:38.664390  8157 raft_consensus.cc:697] T 4439eacba8dd4f8fbe8e75fa82936c6e P c029514ce665498cb57cc7b92168f537 [term 1 LEADER]: Becoming Leader. State: Replica: c029514ce665498cb57cc7b92168f537, State: Running, Role: LEADER
I20260812 06:16:38.664609  8157 consensus_queue.cc:237] T 4439eacba8dd4f8fbe8e75fa82936c6e P c029514ce665498cb57cc7b92168f537 [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: "c029514ce665498cb57cc7b92168f537" member_type: VOTER last_known_addr { host: "127.7.168.65" port: 45337 } }
I20260812 06:16:38.664733  8125 heartbeater.cc:499] Master 127.7.168.126:46837 was elected leader, sending a full tablet report...
I20260812 06:16:38.664472  8152 ts_tablet_manager.cc:1434] T 4439eacba8dd4f8fbe8e75fa82936c6e P c029514ce665498cb57cc7b92168f537: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:16:38.667176  7891 catalog_manager.cc:5719] T 4439eacba8dd4f8fbe8e75fa82936c6e P c029514ce665498cb57cc7b92168f537 reported cstate change: term changed from 0 to 1, leader changed from <none> to c029514ce665498cb57cc7b92168f537 (127.7.168.65). New cstate: current_term: 1 leader_uuid: "c029514ce665498cb57cc7b92168f537" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c029514ce665498cb57cc7b92168f537" member_type: VOTER last_known_addr { host: "127.7.168.65" port: 45337 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:38.730412  7841 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.057s	user 0.018s	sys 0.008s
I20260812 06:16:38.870461  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling FlushMRSOp(4439eacba8dd4f8fbe8e75fa82936c6e): perf score=19.054940
I20260812 06:16:39.059204  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: FlushMRSOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.188s	user 0.140s	sys 0.043s Metrics: {"bytes_written":14276637,"cfile_init":1,"compiler_manager_pool.queue_time_us":287,"delete_count":0,"dirs.queue_time_us":45,"dirs.run_cpu_time_us":219,"dirs.run_wall_time_us":837,"drs_written":1,"lbm_read_time_us":68,"lbm_reads_lt_1ms":4,"lbm_write_time_us":49159,"lbm_writes_lt_1ms":805,"mutex_wait_us":1339,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":155904,"thread_start_us":175,"threads_started":1,"update_count":1740}
I20260812 06:16:39.060717  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling LogGCOp(4439eacba8dd4f8fbe8e75fa82936c6e): free 20290830 bytes of WAL
I20260812 06:16:39.061049  8031 log_reader.cc:385] T 4439eacba8dd4f8fbe8e75fa82936c6e: removed 2 log segments from log reader
I20260812 06:16:39.061129  8031 log.cc:1079] T 4439eacba8dd4f8fbe8e75fa82936c6e P c029514ce665498cb57cc7b92168f537: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/4439eacba8dd4f8fbe8e75fa82936c6e/wal-000000001 (ops 1-6)
I20260812 06:16:39.061198  8031 log.cc:1079] T 4439eacba8dd4f8fbe8e75fa82936c6e P c029514ce665498cb57cc7b92168f537: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/4439eacba8dd4f8fbe8e75fa82936c6e/wal-000000002 (ops 7-10)
I20260812 06:16:39.066533  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: LogGCOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.006s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:16:39.066877  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e): perf score=3.181125
I20260812 06:16:39.087901  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.021s	user 0.010s	sys 0.007s Metrics: {"bytes_written":4841098,"delete_count":0,"lbm_write_time_us":5838,"lbm_writes_lt_1ms":121,"reinsert_count":0,"update_count":590}
I20260812 06:16:39.088400  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e): perf score=1.000000
I20260812 06:16:39.095017  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.006s	user 0.005s	sys 0.000s Metrics: {"bytes_written":1395002,"delete_count":0,"lbm_write_time_us":1813,"lbm_writes_lt_1ms":37,"reinsert_count":0,"update_count":170}
I20260812 06:16:39.095463  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling MajorDeltaCompactionOp(4439eacba8dd4f8fbe8e75fa82936c6e): perf score=1.000000
I20260812 06:16:39.253279  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: MajorDeltaCompactionOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.158s	user 0.106s	sys 0.052s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774738,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":520,"lbm_read_time_us":10978,"lbm_reads_lt_1ms":573,"lbm_write_time_us":26262,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1536,"thread_start_us":333,"threads_started":5,"update_count":2500}
I20260812 06:16:39.253810  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling UndoDeltaBlockGCOp(4439eacba8dd4f8fbe8e75fa82936c6e): 16411392 bytes on disk
I20260812 06:16:39.254354  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: UndoDeltaBlockGCOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":91,"lbm_reads_lt_1ms":4}
I20260812 06:16:39.254875  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e): perf score=10.126437
I20260812 06:16:39.291098  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.036s	user 0.029s	sys 0.004s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":15593,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:39.291531  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e): perf score=2.188937
I20260812 06:16:39.312403  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.021s	user 0.008s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5662,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:39.312870  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling MajorDeltaCompactionOp(4439eacba8dd4f8fbe8e75fa82936c6e): perf score=1.000000
I20260812 06:16:39.439177  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: MajorDeltaCompactionOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.126s	user 0.105s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":94,"lbm_read_time_us":8696,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23421,"lbm_writes_lt_1ms":443,"mutex_wait_us":29,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":16128,"update_count":2000}
I20260812 06:16:39.440469  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e): perf score=10.126437
I20260812 06:16:39.475303  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.035s	user 0.011s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15101,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:39.475835  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e): perf score=2.188937
I20260812 06:16:39.492368  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.016s	user 0.004s	sys 0.011s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6016,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:39.492789  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling MajorDeltaCompactionOp(4439eacba8dd4f8fbe8e75fa82936c6e): perf score=1.000000
I20260812 06:16:39.616830  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: MajorDeltaCompactionOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.124s	user 0.103s	sys 0.020s 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":1575,"lbm_read_time_us":6668,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26364,"lbm_writes_lt_1ms":443,"mutex_wait_us":672,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12160,"update_count":2000}
I20260812 06:16:39.617367  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e): perf score=11.118625
I20260812 06:16:39.649994  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.032s	user 0.018s	sys 0.012s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14344,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:39.650560  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e): perf score=2.188937
I20260812 06:16:39.671130  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.020s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5659,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:39.671579  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling MajorDeltaCompactionOp(4439eacba8dd4f8fbe8e75fa82936c6e): perf score=1.000000
I20260812 06:16:39.788476  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: MajorDeltaCompactionOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.117s	user 0.084s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1006,"lbm_read_time_us":6900,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23457,"lbm_writes_lt_1ms":443,"mutex_wait_us":296,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":29440,"update_count":2000}
I20260812 06:16:39.789101  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e): perf score=11.118625
I20260812 06:16:39.826455  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.037s	user 0.015s	sys 0.020s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":12607,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:39.827092  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e): perf score=2.188937
I20260812 06:16:39.844437  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.017s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5025,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:39.844936  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling MajorDeltaCompactionOp(4439eacba8dd4f8fbe8e75fa82936c6e): perf score=1.000000
I20260812 06:16:40.002609  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: MajorDeltaCompactionOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.157s	user 0.112s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":64,"lbm_read_time_us":9461,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25256,"lbm_writes_lt_1ms":443,"mutex_wait_us":24,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10880,"update_count":2000}
I20260812 06:16:40.003297  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e): perf score=11.118625
I20260812 06:16:40.034709  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.031s	user 0.017s	sys 0.011s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":13181,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:40.035478  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e): perf score=2.188937
I20260812 06:16:40.059010  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.023s	user 0.006s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4790,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:40.059594  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e): perf score=2.188937
I20260812 06:16:40.069866  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3826,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:40.070513  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling MajorDeltaCompactionOp(4439eacba8dd4f8fbe8e75fa82936c6e): perf score=1.000000
I20260812 06:16:40.235289  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: MajorDeltaCompactionOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.165s	user 0.133s	sys 0.018s 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":234,"lbm_read_time_us":10012,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29425,"lbm_writes_lt_1ms":543,"mutex_wait_us":19,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14080,"update_count":2500}
I20260812 06:16:40.236016  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e): perf score=14.095187
I20260812 06:16:40.289552  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.053s	user 0.032s	sys 0.015s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21353,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:40.290066  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e): perf score=2.188937
I20260812 06:16:40.300637  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.010s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3800,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:40.301205  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling FlushMRSOp(4439eacba8dd4f8fbe8e75fa82936c6e): perf score=1.000000
I20260812 06:16:40.332893  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: FlushMRSOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.031s	user 0.027s	sys 0.004s Metrics: {"bytes_written":1275443,"cfile_init":1,"dirs.queue_time_us":61,"dirs.run_cpu_time_us":326,"dirs.run_wall_time_us":1408,"drs_written":1,"lbm_read_time_us":105,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1455,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:16:40.333732  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling LogGCOp(4439eacba8dd4f8fbe8e75fa82936c6e): free 121459501 bytes of WAL
I20260812 06:16:40.333956  8031 log_reader.cc:385] T 4439eacba8dd4f8fbe8e75fa82936c6e: removed 12 log segments from log reader
I20260812 06:16:40.334003  8031 log.cc:1079] T 4439eacba8dd4f8fbe8e75fa82936c6e P c029514ce665498cb57cc7b92168f537: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/4439eacba8dd4f8fbe8e75fa82936c6e/wal-000000003 (ops 11-15)
I20260812 06:16:40.334049  8031 log.cc:1079] T 4439eacba8dd4f8fbe8e75fa82936c6e P c029514ce665498cb57cc7b92168f537: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/4439eacba8dd4f8fbe8e75fa82936c6e/wal-000000004 (ops 16-20)
I20260812 06:16:40.334089  8031 log.cc:1079] T 4439eacba8dd4f8fbe8e75fa82936c6e P c029514ce665498cb57cc7b92168f537: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/4439eacba8dd4f8fbe8e75fa82936c6e/wal-000000005 (ops 21-25)
I20260812 06:16:40.334127  8031 log.cc:1079] T 4439eacba8dd4f8fbe8e75fa82936c6e P c029514ce665498cb57cc7b92168f537: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/4439eacba8dd4f8fbe8e75fa82936c6e/wal-000000006 (ops 26-30)
I20260812 06:16:40.334152  8031 log.cc:1079] T 4439eacba8dd4f8fbe8e75fa82936c6e P c029514ce665498cb57cc7b92168f537: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/4439eacba8dd4f8fbe8e75fa82936c6e/wal-000000007 (ops 31-35)
I20260812 06:16:40.334192  8031 log.cc:1079] T 4439eacba8dd4f8fbe8e75fa82936c6e P c029514ce665498cb57cc7b92168f537: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/4439eacba8dd4f8fbe8e75fa82936c6e/wal-000000008 (ops 36-40)
I20260812 06:16:40.334231  8031 log.cc:1079] T 4439eacba8dd4f8fbe8e75fa82936c6e P c029514ce665498cb57cc7b92168f537: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/4439eacba8dd4f8fbe8e75fa82936c6e/wal-000000009 (ops 41-45)
I20260812 06:16:40.334268  8031 log.cc:1079] T 4439eacba8dd4f8fbe8e75fa82936c6e P c029514ce665498cb57cc7b92168f537: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/4439eacba8dd4f8fbe8e75fa82936c6e/wal-000000010 (ops 46-50)
I20260812 06:16:40.334314  8031 log.cc:1079] T 4439eacba8dd4f8fbe8e75fa82936c6e P c029514ce665498cb57cc7b92168f537: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/4439eacba8dd4f8fbe8e75fa82936c6e/wal-000000011 (ops 51-55)
I20260812 06:16:40.334357  8031 log.cc:1079] T 4439eacba8dd4f8fbe8e75fa82936c6e P c029514ce665498cb57cc7b92168f537: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/4439eacba8dd4f8fbe8e75fa82936c6e/wal-000000012 (ops 56-60)
I20260812 06:16:40.334394  8031 log.cc:1079] T 4439eacba8dd4f8fbe8e75fa82936c6e P c029514ce665498cb57cc7b92168f537: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/4439eacba8dd4f8fbe8e75fa82936c6e/wal-000000013 (ops 61-65)
I20260812 06:16:40.334432  8031 log.cc:1079] T 4439eacba8dd4f8fbe8e75fa82936c6e P c029514ce665498cb57cc7b92168f537: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/4439eacba8dd4f8fbe8e75fa82936c6e/wal-000000014 (ops 66-70)
I20260812 06:16:40.360000  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: LogGCOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.026s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:16:40.360482  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e): perf score=5.165500
I20260812 06:16:40.383214  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.023s	user 0.013s	sys 0.007s Metrics: {"bytes_written":6564114,"delete_count":0,"lbm_write_time_us":6478,"lbm_writes_lt_1ms":163,"reinsert_count":0,"update_count":800}
I20260812 06:16:40.383709  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling LogGCOp(4439eacba8dd4f8fbe8e75fa82936c6e): free 11564875 bytes of WAL
I20260812 06:16:40.383932  8031 log_reader.cc:385] T 4439eacba8dd4f8fbe8e75fa82936c6e: removed 1 log segments from log reader
I20260812 06:16:40.383980  8031 log.cc:1079] T 4439eacba8dd4f8fbe8e75fa82936c6e P c029514ce665498cb57cc7b92168f537: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/4439eacba8dd4f8fbe8e75fa82936c6e/wal-000000015 (ops 71-74)
I20260812 06:16:40.386178  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: LogGCOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:16:40.386490  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling UndoDeltaBlockGCOp(4439eacba8dd4f8fbe8e75fa82936c6e): 483 bytes on disk
I20260812 06:16:40.386924  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: UndoDeltaBlockGCOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4}
I20260812 06:16:40.387356  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e): perf score=1.000000
I20260812 06:16:40.393733  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.006s	user 0.004s	sys 0.001s Metrics: {"bytes_written":1641152,"delete_count":0,"lbm_write_time_us":1540,"lbm_writes_lt_1ms":43,"reinsert_count":0,"update_count":200}
I20260812 06:16:40.394181  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling MajorDeltaCompactionOp(4439eacba8dd4f8fbe8e75fa82936c6e): perf score=1.000000
I20260812 06:16:40.613880  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: MajorDeltaCompactionOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.220s	user 0.152s	sys 0.065s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979694,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":480,"lbm_read_time_us":15645,"lbm_reads_lt_1ms":774,"lbm_write_time_us":38829,"lbm_writes_lt_1ms":743,"mutex_wait_us":26,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":12928,"thread_start_us":87,"threads_started":1,"update_count":3500}
I20260812 06:16:40.614527  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e): perf score=14.095187
I20260812 06:16:40.668156  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.053s	user 0.023s	sys 0.028s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24174,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:40.668804  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e): perf score=2.188937
I20260812 06:16:40.680416  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.011s	user 0.002s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4241,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:40.680920  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling MajorDeltaCompactionOp(4439eacba8dd4f8fbe8e75fa82936c6e): perf score=1.000000
I20260812 06:16:40.848457  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: MajorDeltaCompactionOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.167s	user 0.104s	sys 0.060s 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":163,"lbm_read_time_us":12757,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27891,"lbm_writes_lt_1ms":543,"mutex_wait_us":45,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":73344,"update_count":2500}
I20260812 06:16:40.849151  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e): perf score=11.118625
I20260812 06:16:40.890818  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.041s	user 0.010s	sys 0.029s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":17933,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:40.891284  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e): perf score=2.188937
I20260812 06:16:40.923717  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.032s	user 0.012s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6527,"lbm_writes_lt_1ms":93,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":450}
I20260812 06:16:40.924225  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e): perf score=2.188937
I20260812 06:16:40.935071  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4092,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:40.935518  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling MajorDeltaCompactionOp(4439eacba8dd4f8fbe8e75fa82936c6e): perf score=1.000000
I20260812 06:16:41.116986  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: MajorDeltaCompactionOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.181s	user 0.126s	sys 0.045s 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":542,"lbm_read_time_us":13161,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29032,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:16:41.117602  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e): perf score=14.095187
I20260812 06:16:41.180976  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.061s	user 0.037s	sys 0.023s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23173,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:41.181622  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e): perf score=2.188937
I20260812 06:16:41.197961  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.016s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6168,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:41.198567  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling MajorDeltaCompactionOp(4439eacba8dd4f8fbe8e75fa82936c6e): perf score=1.000000
I20260812 06:16:41.381676  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: MajorDeltaCompactionOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.183s	user 0.126s	sys 0.047s 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":965,"lbm_read_time_us":13057,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29761,"lbm_writes_lt_1ms":543,"mutex_wait_us":276,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9088,"update_count":2500}
I20260812 06:16:41.382220  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e): perf score=14.095187
I20260812 06:16:41.430388  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.048s	user 0.019s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18427,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:41.430932  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e): perf score=2.188937
I20260812 06:16:41.446187  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5713,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:41.446753  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling MajorDeltaCompactionOp(4439eacba8dd4f8fbe8e75fa82936c6e): perf score=1.000000
I20260812 06:16:41.616403  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: MajorDeltaCompactionOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.169s	user 0.117s	sys 0.048s 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":1084,"lbm_read_time_us":11075,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27701,"lbm_writes_lt_1ms":543,"mutex_wait_us":284,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2944,"update_count":2500}
I20260812 06:16:41.617265  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e): perf score=11.118625
I20260812 06:16:41.655673  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.038s	user 0.030s	sys 0.005s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16480,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:41.656239  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e): perf score=2.188937
I20260812 06:16:41.680871  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.024s	user 0.006s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5580,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:41.681412  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e): perf score=2.188937
I20260812 06:16:41.691679  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3982,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:41.692190  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling MajorDeltaCompactionOp(4439eacba8dd4f8fbe8e75fa82936c6e): perf score=1.000000
I20260812 06:16:41.837751  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: MajorDeltaCompactionOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.145s	user 0.125s	sys 0.020s 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":225,"lbm_read_time_us":9758,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30066,"lbm_writes_lt_1ms":543,"mutex_wait_us":26,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7936,"update_count":2500}
I20260812 06:16:41.838464  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e): perf score=10.126437
I20260812 06:16:41.877350  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.039s	user 0.010s	sys 0.028s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18402,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:16:41.877874  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e): perf score=2.188937
I20260812 06:16:41.894758  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.017s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4750,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:41.895278  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling FlushMRSOp(4439eacba8dd4f8fbe8e75fa82936c6e): perf score=1.000000
I20260812 06:16:41.922884  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: FlushMRSOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.027s	user 0.026s	sys 0.000s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":67,"dirs.run_cpu_time_us":221,"dirs.run_wall_time_us":1347,"drs_written":1,"lbm_read_time_us":36,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1559,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:16:41.923668  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling LogGCOp(4439eacba8dd4f8fbe8e75fa82936c6e): free 121006462 bytes of WAL
I20260812 06:16:41.923892  8031 log_reader.cc:385] T 4439eacba8dd4f8fbe8e75fa82936c6e: removed 12 log segments from log reader
I20260812 06:16:41.923939  8031 log.cc:1079] T 4439eacba8dd4f8fbe8e75fa82936c6e P c029514ce665498cb57cc7b92168f537: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/4439eacba8dd4f8fbe8e75fa82936c6e/wal-000000016 (ops 75-79)
I20260812 06:16:41.923969  8031 log.cc:1079] T 4439eacba8dd4f8fbe8e75fa82936c6e P c029514ce665498cb57cc7b92168f537: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/4439eacba8dd4f8fbe8e75fa82936c6e/wal-000000017 (ops 80-84)
I20260812 06:16:41.924029  8031 log.cc:1079] T 4439eacba8dd4f8fbe8e75fa82936c6e P c029514ce665498cb57cc7b92168f537: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/4439eacba8dd4f8fbe8e75fa82936c6e/wal-000000018 (ops 85-89)
I20260812 06:16:41.924075  8031 log.cc:1079] T 4439eacba8dd4f8fbe8e75fa82936c6e P c029514ce665498cb57cc7b92168f537: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/4439eacba8dd4f8fbe8e75fa82936c6e/wal-000000019 (ops 90-94)
I20260812 06:16:41.924111  8031 log.cc:1079] T 4439eacba8dd4f8fbe8e75fa82936c6e P c029514ce665498cb57cc7b92168f537: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/4439eacba8dd4f8fbe8e75fa82936c6e/wal-000000020 (ops 95-98)
I20260812 06:16:41.924165  8031 log.cc:1079] T 4439eacba8dd4f8fbe8e75fa82936c6e P c029514ce665498cb57cc7b92168f537: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/4439eacba8dd4f8fbe8e75fa82936c6e/wal-000000021 (ops 99-103)
I20260812 06:16:41.924206  8031 log.cc:1079] T 4439eacba8dd4f8fbe8e75fa82936c6e P c029514ce665498cb57cc7b92168f537: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/4439eacba8dd4f8fbe8e75fa82936c6e/wal-000000022 (ops 104-108)
I20260812 06:16:41.924350  8031 log.cc:1079] T 4439eacba8dd4f8fbe8e75fa82936c6e P c029514ce665498cb57cc7b92168f537: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/4439eacba8dd4f8fbe8e75fa82936c6e/wal-000000023 (ops 109-113)
I20260812 06:16:41.924396  8031 log.cc:1079] T 4439eacba8dd4f8fbe8e75fa82936c6e P c029514ce665498cb57cc7b92168f537: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/4439eacba8dd4f8fbe8e75fa82936c6e/wal-000000024 (ops 114-118)
I20260812 06:16:41.924415  8031 log.cc:1079] T 4439eacba8dd4f8fbe8e75fa82936c6e P c029514ce665498cb57cc7b92168f537: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/4439eacba8dd4f8fbe8e75fa82936c6e/wal-000000025 (ops 119-123)
I20260812 06:16:41.924453  8031 log.cc:1079] T 4439eacba8dd4f8fbe8e75fa82936c6e P c029514ce665498cb57cc7b92168f537: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/4439eacba8dd4f8fbe8e75fa82936c6e/wal-000000026 (ops 124-128)
I20260812 06:16:41.924495  8031 log.cc:1079] T 4439eacba8dd4f8fbe8e75fa82936c6e P c029514ce665498cb57cc7b92168f537: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/4439eacba8dd4f8fbe8e75fa82936c6e/wal-000000027 (ops 129-133)
I20260812 06:16:41.949429  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: LogGCOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.026s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:16:41.949856  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e): perf score=5.165500
I20260812 06:16:41.965582  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.016s	user 0.014s	sys 0.000s Metrics: {"bytes_written":6317965,"delete_count":0,"lbm_write_time_us":6230,"lbm_writes_lt_1ms":157,"reinsert_count":0,"update_count":770}
I20260812 06:16:41.966219  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling UndoDeltaBlockGCOp(4439eacba8dd4f8fbe8e75fa82936c6e): 482 bytes on disk
I20260812 06:16:41.966745  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: UndoDeltaBlockGCOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4}
I20260812 06:16:41.967345  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e): perf score=1.000000
I20260812 06:16:41.984970  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.017s	user 0.007s	sys 0.007s Metrics: {"bytes_written":1887302,"delete_count":0,"lbm_write_time_us":2905,"lbm_writes_lt_1ms":49,"reinsert_count":0,"update_count":230}
I20260812 06:16:41.985545  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling MajorDeltaCompactionOp(4439eacba8dd4f8fbe8e75fa82936c6e): perf score=1.000000
I20260812 06:16:42.176831  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: MajorDeltaCompactionOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.191s	user 0.124s	sys 0.066s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877282,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1508,"lbm_read_time_us":12286,"lbm_reads_lt_1ms":666,"lbm_write_time_us":32705,"lbm_writes_lt_1ms":643,"mutex_wait_us":22,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":7936,"thread_start_us":92,"threads_started":1,"update_count":3000}
I20260812 06:16:42.177657  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e): perf score=14.095187
I20260812 06:16:42.224745  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.047s	user 0.032s	sys 0.013s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20289,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:42.225538  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e): perf score=2.188937
I20260812 06:16:42.254456  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.029s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4839,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:42.255029  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e): perf score=2.188937
I20260812 06:16:42.271947  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.017s	user 0.003s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6940,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:42.272475  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling MajorDeltaCompactionOp(4439eacba8dd4f8fbe8e75fa82936c6e): perf score=1.000000
I20260812 06:16:42.462930  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: MajorDeltaCompactionOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.190s	user 0.144s	sys 0.045s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877219,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":142,"lbm_read_time_us":13438,"lbm_reads_lt_1ms":673,"lbm_write_time_us":33453,"lbm_writes_lt_1ms":643,"mutex_wait_us":44,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":3000}
I20260812 06:16:42.463488  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e): perf score=14.095187
I20260812 06:16:42.529058  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.065s	user 0.037s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24319,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:16:42.529529  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e): perf score=2.188937
I20260812 06:16:42.544894  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.015s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5809,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:42.545328  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling MajorDeltaCompactionOp(4439eacba8dd4f8fbe8e75fa82936c6e): perf score=1.000000
I20260812 06:16:42.721056  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: MajorDeltaCompactionOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.176s	user 0.121s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1146,"lbm_read_time_us":12194,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30729,"lbm_writes_lt_1ms":543,"mutex_wait_us":279,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:16:42.721590  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e): perf score=11.118625
I20260812 06:16:42.756265  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.034s	user 0.018s	sys 0.014s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":14337,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:42.756794  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e): perf score=2.188937
I20260812 06:16:42.792080  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.035s	user 0.011s	sys 0.012s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6446,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:42.792673  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e): perf score=2.188937
I20260812 06:16:42.808488  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.016s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5912,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:42.809026  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling MajorDeltaCompactionOp(4439eacba8dd4f8fbe8e75fa82936c6e): perf score=1.000000
I20260812 06:16:42.978091  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: MajorDeltaCompactionOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.169s	user 0.116s	sys 0.052s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774800,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":271,"lbm_read_time_us":12703,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29270,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6528,"update_count":2500}
I20260812 06:16:42.978653  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e): perf score=10.126437
I20260812 06:16:43.018708  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.039s	user 0.025s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17553,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:43.019237  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e): perf score=2.188937
I20260812 06:16:43.029899  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4080,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:43.030658  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling MajorDeltaCompactionOp(4439eacba8dd4f8fbe8e75fa82936c6e): perf score=1.000000
I20260812 06:16:43.159873  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: MajorDeltaCompactionOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.129s	user 0.095s	sys 0.030s 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":403,"lbm_read_time_us":8989,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24050,"lbm_writes_lt_1ms":443,"mutex_wait_us":86,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12928,"update_count":2000}
I20260812 06:16:43.160641  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e): perf score=10.126437
I20260812 06:16:43.206430  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.046s	user 0.010s	sys 0.021s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14490,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:43.206981  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e): perf score=2.188937
I20260812 06:16:43.219370  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4072,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:43.219887  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling MajorDeltaCompactionOp(4439eacba8dd4f8fbe8e75fa82936c6e): perf score=1.000000
I20260812 06:16:43.356051  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: MajorDeltaCompactionOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.136s	user 0.094s	sys 0.041s 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":249,"lbm_read_time_us":8977,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27692,"lbm_writes_lt_1ms":443,"mutex_wait_us":38,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2000}
I20260812 06:16:43.356715  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e): perf score=10.126437
I20260812 06:16:43.394326  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.037s	user 0.014s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18645,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:16:43.395949  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e): perf score=2.188937
I20260812 06:16:43.410279  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5532,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:43.410784  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling FlushMRSOp(4439eacba8dd4f8fbe8e75fa82936c6e): perf score=1.000000
I20260812 06:16:43.464039  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: FlushMRSOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.053s	user 0.028s	sys 0.004s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":53,"dirs.run_cpu_time_us":175,"dirs.run_wall_time_us":1339,"drs_written":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1642,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:16:43.464928  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling LogGCOp(4439eacba8dd4f8fbe8e75fa82936c6e): free 128414672 bytes of WAL
I20260812 06:16:43.465191  8031 log_reader.cc:385] T 4439eacba8dd4f8fbe8e75fa82936c6e: removed 13 log segments from log reader
I20260812 06:16:43.465262  8031 log.cc:1079] T 4439eacba8dd4f8fbe8e75fa82936c6e P c029514ce665498cb57cc7b92168f537: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/4439eacba8dd4f8fbe8e75fa82936c6e/wal-000000028 (ops 134-138)
I20260812 06:16:43.465317  8031 log.cc:1079] T 4439eacba8dd4f8fbe8e75fa82936c6e P c029514ce665498cb57cc7b92168f537: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/4439eacba8dd4f8fbe8e75fa82936c6e/wal-000000029 (ops 139-142)
I20260812 06:16:43.465368  8031 log.cc:1079] T 4439eacba8dd4f8fbe8e75fa82936c6e P c029514ce665498cb57cc7b92168f537: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/4439eacba8dd4f8fbe8e75fa82936c6e/wal-000000030 (ops 143-147)
I20260812 06:16:43.465409  8031 log.cc:1079] T 4439eacba8dd4f8fbe8e75fa82936c6e P c029514ce665498cb57cc7b92168f537: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/4439eacba8dd4f8fbe8e75fa82936c6e/wal-000000031 (ops 148-152)
I20260812 06:16:43.465456  8031 log.cc:1079] T 4439eacba8dd4f8fbe8e75fa82936c6e P c029514ce665498cb57cc7b92168f537: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/4439eacba8dd4f8fbe8e75fa82936c6e/wal-000000032 (ops 153-157)
I20260812 06:16:43.465498  8031 log.cc:1079] T 4439eacba8dd4f8fbe8e75fa82936c6e P c029514ce665498cb57cc7b92168f537: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/4439eacba8dd4f8fbe8e75fa82936c6e/wal-000000033 (ops 158-162)
I20260812 06:16:43.465536  8031 log.cc:1079] T 4439eacba8dd4f8fbe8e75fa82936c6e P c029514ce665498cb57cc7b92168f537: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/4439eacba8dd4f8fbe8e75fa82936c6e/wal-000000034 (ops 163-166)
I20260812 06:16:43.465572  8031 log.cc:1079] T 4439eacba8dd4f8fbe8e75fa82936c6e P c029514ce665498cb57cc7b92168f537: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/4439eacba8dd4f8fbe8e75fa82936c6e/wal-000000035 (ops 167-171)
I20260812 06:16:43.465610  8031 log.cc:1079] T 4439eacba8dd4f8fbe8e75fa82936c6e P c029514ce665498cb57cc7b92168f537: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/4439eacba8dd4f8fbe8e75fa82936c6e/wal-000000036 (ops 172-176)
I20260812 06:16:43.465646  8031 log.cc:1079] T 4439eacba8dd4f8fbe8e75fa82936c6e P c029514ce665498cb57cc7b92168f537: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/4439eacba8dd4f8fbe8e75fa82936c6e/wal-000000037 (ops 177-180)
I20260812 06:16:43.465683  8031 log.cc:1079] T 4439eacba8dd4f8fbe8e75fa82936c6e P c029514ce665498cb57cc7b92168f537: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/4439eacba8dd4f8fbe8e75fa82936c6e/wal-000000038 (ops 181-185)
I20260812 06:16:43.465720  8031 log.cc:1079] T 4439eacba8dd4f8fbe8e75fa82936c6e P c029514ce665498cb57cc7b92168f537: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/4439eacba8dd4f8fbe8e75fa82936c6e/wal-000000039 (ops 186-190)
I20260812 06:16:43.465806  8031 log.cc:1079] T 4439eacba8dd4f8fbe8e75fa82936c6e P c029514ce665498cb57cc7b92168f537: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/4439eacba8dd4f8fbe8e75fa82936c6e/wal-000000040 (ops 191-194)
I20260812 06:16:43.490906  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: LogGCOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.026s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:16:43.491340  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e): perf score=7.149875
I20260812 06:16:43.518028  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.026s	user 0.005s	sys 0.020s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":11728,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:16:43.518534  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling UndoDeltaBlockGCOp(4439eacba8dd4f8fbe8e75fa82936c6e): 481 bytes on disk
I20260812 06:16:43.518940  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: UndoDeltaBlockGCOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4}
I20260812 06:16:43.519469  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e): perf score=2.188937
I20260812 06:16:43.531133  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: FlushDeltaMemStoresOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4024,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:43.531651  8126 maintenance_manager.cc:419] P c029514ce665498cb57cc7b92168f537: Scheduling MajorDeltaCompactionOp(4439eacba8dd4f8fbe8e75fa82936c6e): perf score=1.000000
I20260812 06:16:43.556742  7841 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.826s	user 1.790s	sys 0.162s
I20260812 06:16:43.654711  7841 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.097s	user 0.002s	sys 0.000s
I20260812 06:16:43.655349  7841 tablet_server.cc:179] TabletServer@127.7.168.65:0 shutting down...
I20260812 06:16:43.710850  8031 maintenance_manager.cc:643] P c029514ce665498cb57cc7b92168f537: MajorDeltaCompactionOp(4439eacba8dd4f8fbe8e75fa82936c6e) complete. Timing: real 0.179s	user 0.134s	sys 0.044s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979742,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1315,"lbm_read_time_us":15049,"lbm_reads_lt_1ms":770,"lbm_write_time_us":32817,"lbm_writes_lt_1ms":743,"mutex_wait_us":352,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":13952,"thread_start_us":71,"threads_started":1,"update_count":3500}
I20260812 06:16:43.711465  7841 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:16:43.711941  7841 tablet_replica.cc:333] T 4439eacba8dd4f8fbe8e75fa82936c6e P c029514ce665498cb57cc7b92168f537: stopping tablet replica
I20260812 06:16:43.712123  7841 raft_consensus.cc:2243] T 4439eacba8dd4f8fbe8e75fa82936c6e P c029514ce665498cb57cc7b92168f537 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:43.712374  7841 raft_consensus.cc:2272] T 4439eacba8dd4f8fbe8e75fa82936c6e P c029514ce665498cb57cc7b92168f537 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:43.718394  7841 tablet_server.cc:196] TabletServer@127.7.168.65:0 shutdown complete.
I20260812 06:16:43.773703  7841 master.cc:562] Master@127.7.168.126:46837 shutting down...
I20260812 06:16:43.777848  7841 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 3991fc5573a84538822721d95c2b17b4 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:43.778038  7841 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 3991fc5573a84538822721d95c2b17b4 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:43.778124  7841 tablet_replica.cc:333] T 00000000000000000000000000000000 P 3991fc5573a84538822721d95c2b17b4: stopping tablet replica
I20260812 06:16:43.790374  7841 master.cc:584] Master@127.7.168.126:46837 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5419 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:16:43.872486  7841 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.7.168.126:39905
I20260812 06:16:43.872881  7841 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:16:43.875226  7841 server_base.cc:1061] running on GCE node
W20260812 06:16:43.875172  8192 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:16:43.875324  8189 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:16:43.875356  8190 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:16:43.875586  7841 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:43.875629  7841 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:16:43.875644  7841 hybrid_clock.cc:648] HybridClock initialized: now 1786515403875644 us; error 0 us; skew 500 ppm
I20260812 06:16:43.876580  7841 webserver.cc:533] Webserver started at http://127.7.168.126:40965/ using document root <none> and password file <none>
I20260812 06:16:43.876750  7841 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:43.876796  7841 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:43.876892  7841 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:43.877377  7841 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398442455-7841-0/minicluster-data/master-0-root/instance:
uuid: "1adb1fb039cc46f78492ae9a6d812815"
format_stamp: "Formatted at 2026-08-12 06:16:43 on dist-test-slave-45dx"
I20260812 06:16:43.878897  7841 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:16:43.879788  8201 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:16:43.880045  7841 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:43.880113  7841 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398442455-7841-0/minicluster-data/master-0-root
uuid: "1adb1fb039cc46f78492ae9a6d812815"
format_stamp: "Formatted at 2026-08-12 06:16:43 on dist-test-slave-45dx"
I20260812 06:16:43.880206  7841 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398442455-7841-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398442455-7841-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398442455-7841-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:16:43.894558  7841 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:43.894934  7841 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:43.899088  7841 rpc_server.cc:307] RPC server started. Bound to: 127.7.168.126:39905
I20260812 06:16:43.901548  8293 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.7.168.126:39905 every 8 connection(s)
I20260812 06:16:43.902307  8295 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:16:43.915624  8295 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 1adb1fb039cc46f78492ae9a6d812815: Bootstrap starting.
I20260812 06:16:43.916479  8295 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 1adb1fb039cc46f78492ae9a6d812815: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:43.917590  8295 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 1adb1fb039cc46f78492ae9a6d812815: No bootstrap required, opened a new log
I20260812 06:16:43.917989  8295 raft_consensus.cc:359] T 00000000000000000000000000000000 P 1adb1fb039cc46f78492ae9a6d812815 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1adb1fb039cc46f78492ae9a6d812815" member_type: VOTER }
I20260812 06:16:43.918078  8295 raft_consensus.cc:385] T 00000000000000000000000000000000 P 1adb1fb039cc46f78492ae9a6d812815 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:43.918144  8295 raft_consensus.cc:740] T 00000000000000000000000000000000 P 1adb1fb039cc46f78492ae9a6d812815 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 1adb1fb039cc46f78492ae9a6d812815, State: Initialized, Role: FOLLOWER
I20260812 06:16:43.918319  8295 consensus_queue.cc:260] T 00000000000000000000000000000000 P 1adb1fb039cc46f78492ae9a6d812815 [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: "1adb1fb039cc46f78492ae9a6d812815" member_type: VOTER }
I20260812 06:16:43.918412  8295 raft_consensus.cc:399] T 00000000000000000000000000000000 P 1adb1fb039cc46f78492ae9a6d812815 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:43.918478  8295 raft_consensus.cc:493] T 00000000000000000000000000000000 P 1adb1fb039cc46f78492ae9a6d812815 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:43.918537  8295 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 1adb1fb039cc46f78492ae9a6d812815 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:43.919225  8295 raft_consensus.cc:515] T 00000000000000000000000000000000 P 1adb1fb039cc46f78492ae9a6d812815 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1adb1fb039cc46f78492ae9a6d812815" member_type: VOTER }
I20260812 06:16:43.919374  8295 leader_election.cc:304] T 00000000000000000000000000000000 P 1adb1fb039cc46f78492ae9a6d812815 [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: 1adb1fb039cc46f78492ae9a6d812815; no voters: 
I20260812 06:16:43.919584  8295 leader_election.cc:290] T 00000000000000000000000000000000 P 1adb1fb039cc46f78492ae9a6d812815 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:43.919701  8299 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 1adb1fb039cc46f78492ae9a6d812815 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:43.919955  8299 raft_consensus.cc:697] T 00000000000000000000000000000000 P 1adb1fb039cc46f78492ae9a6d812815 [term 1 LEADER]: Becoming Leader. State: Replica: 1adb1fb039cc46f78492ae9a6d812815, State: Running, Role: LEADER
I20260812 06:16:43.920013  8295 sys_catalog.cc:565] T 00000000000000000000000000000000 P 1adb1fb039cc46f78492ae9a6d812815 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:43.920101  8299 consensus_queue.cc:237] T 00000000000000000000000000000000 P 1adb1fb039cc46f78492ae9a6d812815 [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: "1adb1fb039cc46f78492ae9a6d812815" member_type: VOTER }
I20260812 06:16:43.920583  8302 sys_catalog.cc:455] T 00000000000000000000000000000000 P 1adb1fb039cc46f78492ae9a6d812815 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 1adb1fb039cc46f78492ae9a6d812815. Latest consensus state: current_term: 1 leader_uuid: "1adb1fb039cc46f78492ae9a6d812815" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1adb1fb039cc46f78492ae9a6d812815" member_type: VOTER } }
I20260812 06:16:43.920569  8300 sys_catalog.cc:455] T 00000000000000000000000000000000 P 1adb1fb039cc46f78492ae9a6d812815 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "1adb1fb039cc46f78492ae9a6d812815" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1adb1fb039cc46f78492ae9a6d812815" member_type: VOTER } }
I20260812 06:16:43.920717  8302 sys_catalog.cc:458] T 00000000000000000000000000000000 P 1adb1fb039cc46f78492ae9a6d812815 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:43.920809  8300 sys_catalog.cc:458] T 00000000000000000000000000000000 P 1adb1fb039cc46f78492ae9a6d812815 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:43.921362  8315 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:43.922250  8315 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:43.922479  7841 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:43.924036  8315 catalog_manager.cc:1383] Generated new cluster ID: acf3ddf5ebc4468488abc1c25a0cb0e8
I20260812 06:16:43.924096  8315 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:43.930824  8315 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:43.931303  8315 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:43.936549  8315 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 1adb1fb039cc46f78492ae9a6d812815: Generated new TSK 0
I20260812 06:16:43.936691  8315 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:43.938478  7841 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:43.940150  8330 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:16:43.940240  8335 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:16:43.940325  8337 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:16:43.940430  7841 server_base.cc:1061] running on GCE node
I20260812 06:16:43.940714  7841 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:43.940773  7841 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:16:43.940796  7841 hybrid_clock.cc:648] HybridClock initialized: now 1786515403940796 us; error 0 us; skew 500 ppm
I20260812 06:16:43.941578  7841 webserver.cc:533] Webserver started at http://127.7.168.65:43109/ using document root <none> and password file <none>
I20260812 06:16:43.941759  7841 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:43.941828  7841 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:43.941917  7841 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:43.942287  7841 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398442455-7841-0/minicluster-data/ts-0-root/instance:
uuid: "8861b0bf87134f88b5b93aec1aa63d3a"
format_stamp: "Formatted at 2026-08-12 06:16:43 on dist-test-slave-45dx"
I20260812 06:16:43.943718  7841 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:16:43.944656  8349 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:16:43.944950  7841 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:16:43.945039  7841 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398442455-7841-0/minicluster-data/ts-0-root
uuid: "8861b0bf87134f88b5b93aec1aa63d3a"
format_stamp: "Formatted at 2026-08-12 06:16:43 on dist-test-slave-45dx"
I20260812 06:16:43.945116  7841 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398442455-7841-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398442455-7841-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398442455-7841-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:16:43.953329  7841 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:43.953651  7841 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:43.953929  7841 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:43.954355  7841 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:43.954412  7841 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:43.954459  7841 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:43.954504  7841 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:43.958591  7841 rpc_server.cc:307] RPC server started. Bound to: 127.7.168.65:46021
I20260812 06:16:43.958649  8447 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.7.168.65:46021 every 8 connection(s)
I20260812 06:16:43.966915  8449 heartbeater.cc:344] Connected to a master server at 127.7.168.126:39905
I20260812 06:16:43.967041  8449 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:43.967258  8449 heartbeater.cc:507] Master 127.7.168.126:39905 requested a full tablet report, sending...
I20260812 06:16:43.967928  8228 ts_manager.cc:194] Registered new tserver with Master: 8861b0bf87134f88b5b93aec1aa63d3a (127.7.168.65:46021)
I20260812 06:16:43.968662  8228 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:42916
I20260812 06:16:43.968859  7841 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.009838969s
I20260812 06:16:43.975313  8228 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:42928:
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:16:43.983593  8392 tablet_service.cc:1511] Processing CreateTablet for tablet 835731265bd54d31b267935835cd167d (DEFAULT_TABLE table=heavy-update-compaction-test [id=29c595c0d7f047669b7244d15e6afff9]), partition=
I20260812 06:16:43.983877  8392 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 835731265bd54d31b267935835cd167d. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:43.985846  8471 tablet_bootstrap.cc:492] T 835731265bd54d31b267935835cd167d P 8861b0bf87134f88b5b93aec1aa63d3a: Bootstrap starting.
I20260812 06:16:43.986726  8471 tablet_bootstrap.cc:654] T 835731265bd54d31b267935835cd167d P 8861b0bf87134f88b5b93aec1aa63d3a: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:43.987766  8471 tablet_bootstrap.cc:492] T 835731265bd54d31b267935835cd167d P 8861b0bf87134f88b5b93aec1aa63d3a: No bootstrap required, opened a new log
I20260812 06:16:43.987860  8471 ts_tablet_manager.cc:1403] T 835731265bd54d31b267935835cd167d P 8861b0bf87134f88b5b93aec1aa63d3a: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:16:43.988272  8471 raft_consensus.cc:359] T 835731265bd54d31b267935835cd167d P 8861b0bf87134f88b5b93aec1aa63d3a [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8861b0bf87134f88b5b93aec1aa63d3a" member_type: VOTER last_known_addr { host: "127.7.168.65" port: 46021 } }
I20260812 06:16:43.988412  8471 raft_consensus.cc:385] T 835731265bd54d31b267935835cd167d P 8861b0bf87134f88b5b93aec1aa63d3a [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:43.988476  8471 raft_consensus.cc:740] T 835731265bd54d31b267935835cd167d P 8861b0bf87134f88b5b93aec1aa63d3a [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 8861b0bf87134f88b5b93aec1aa63d3a, State: Initialized, Role: FOLLOWER
I20260812 06:16:43.988632  8471 consensus_queue.cc:260] T 835731265bd54d31b267935835cd167d P 8861b0bf87134f88b5b93aec1aa63d3a [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: "8861b0bf87134f88b5b93aec1aa63d3a" member_type: VOTER last_known_addr { host: "127.7.168.65" port: 46021 } }
I20260812 06:16:43.988724  8471 raft_consensus.cc:399] T 835731265bd54d31b267935835cd167d P 8861b0bf87134f88b5b93aec1aa63d3a [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:43.988773  8471 raft_consensus.cc:493] T 835731265bd54d31b267935835cd167d P 8861b0bf87134f88b5b93aec1aa63d3a [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:43.988826  8471 raft_consensus.cc:3060] T 835731265bd54d31b267935835cd167d P 8861b0bf87134f88b5b93aec1aa63d3a [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:43.989527  8471 raft_consensus.cc:515] T 835731265bd54d31b267935835cd167d P 8861b0bf87134f88b5b93aec1aa63d3a [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8861b0bf87134f88b5b93aec1aa63d3a" member_type: VOTER last_known_addr { host: "127.7.168.65" port: 46021 } }
I20260812 06:16:43.989677  8471 leader_election.cc:304] T 835731265bd54d31b267935835cd167d P 8861b0bf87134f88b5b93aec1aa63d3a [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: 8861b0bf87134f88b5b93aec1aa63d3a; no voters: 
I20260812 06:16:43.989880  8471 leader_election.cc:290] T 835731265bd54d31b267935835cd167d P 8861b0bf87134f88b5b93aec1aa63d3a [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:43.990001  8473 raft_consensus.cc:2804] T 835731265bd54d31b267935835cd167d P 8861b0bf87134f88b5b93aec1aa63d3a [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:43.990236  8449 heartbeater.cc:499] Master 127.7.168.126:39905 was elected leader, sending a full tablet report...
I20260812 06:16:43.990231  8471 ts_tablet_manager.cc:1434] T 835731265bd54d31b267935835cd167d P 8861b0bf87134f88b5b93aec1aa63d3a: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:16:43.990260  8473 raft_consensus.cc:697] T 835731265bd54d31b267935835cd167d P 8861b0bf87134f88b5b93aec1aa63d3a [term 1 LEADER]: Becoming Leader. State: Replica: 8861b0bf87134f88b5b93aec1aa63d3a, State: Running, Role: LEADER
I20260812 06:16:43.990501  8473 consensus_queue.cc:237] T 835731265bd54d31b267935835cd167d P 8861b0bf87134f88b5b93aec1aa63d3a [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: "8861b0bf87134f88b5b93aec1aa63d3a" member_type: VOTER last_known_addr { host: "127.7.168.65" port: 46021 } }
I20260812 06:16:43.991652  8228 catalog_manager.cc:5719] T 835731265bd54d31b267935835cd167d P 8861b0bf87134f88b5b93aec1aa63d3a reported cstate change: term changed from 0 to 1, leader changed from <none> to 8861b0bf87134f88b5b93aec1aa63d3a (127.7.168.65). New cstate: current_term: 1 leader_uuid: "8861b0bf87134f88b5b93aec1aa63d3a" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8861b0bf87134f88b5b93aec1aa63d3a" member_type: VOTER last_known_addr { host: "127.7.168.65" port: 46021 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:44.050199  7841 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.051s	user 0.022s	sys 0.000s
I20260812 06:16:44.209476  8452 maintenance_manager.cc:419] P 8861b0bf87134f88b5b93aec1aa63d3a: Scheduling FlushMRSOp(835731265bd54d31b267935835cd167d): perf score=19.054940
I20260812 06:16:44.369371  8356 maintenance_manager.cc:643] P 8861b0bf87134f88b5b93aec1aa63d3a: FlushMRSOp(835731265bd54d31b267935835cd167d) complete. Timing: real 0.160s	user 0.108s	sys 0.048s Metrics: {"bytes_written":15999660,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":65,"dirs.run_cpu_time_us":213,"dirs.run_wall_time_us":867,"drs_written":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4,"lbm_write_time_us":42581,"lbm_writes_lt_1ms":857,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"update_count":1950}
I20260812 06:16:44.370271  8452 maintenance_manager.cc:419] P 8861b0bf87134f88b5b93aec1aa63d3a: Scheduling LogGCOp(835731265bd54d31b267935835cd167d): free 20743880 bytes of WAL
I20260812 06:16:44.370512  8356 log_reader.cc:385] T 835731265bd54d31b267935835cd167d: removed 2 log segments from log reader
I20260812 06:16:44.370570  8356 log.cc:1079] T 835731265bd54d31b267935835cd167d P 8861b0bf87134f88b5b93aec1aa63d3a: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/835731265bd54d31b267935835cd167d/wal-000000001 (ops 1-6)
I20260812 06:16:44.370669  8356 log.cc:1079] T 835731265bd54d31b267935835cd167d P 8861b0bf87134f88b5b93aec1aa63d3a: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/835731265bd54d31b267935835cd167d/wal-000000002 (ops 7-11)
I20260812 06:16:44.374897  8356 maintenance_manager.cc:643] P 8861b0bf87134f88b5b93aec1aa63d3a: LogGCOp(835731265bd54d31b267935835cd167d) complete. Timing: real 0.004s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:16:44.375222  8452 maintenance_manager.cc:419] P 8861b0bf87134f88b5b93aec1aa63d3a: Scheduling FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d): perf score=2.188937
I20260812 06:16:44.391712  8356 maintenance_manager.cc:643] P 8861b0bf87134f88b5b93aec1aa63d3a: FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d) complete. Timing: real 0.016s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4517,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:44.392225  8452 maintenance_manager.cc:419] P 8861b0bf87134f88b5b93aec1aa63d3a: Scheduling UndoDeltaBlockGCOp(835731265bd54d31b267935835cd167d): 16821650 bytes on disk
I20260812 06:16:44.392764  8356 maintenance_manager.cc:643] P 8861b0bf87134f88b5b93aec1aa63d3a: UndoDeltaBlockGCOp(835731265bd54d31b267935835cd167d) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":77,"lbm_reads_lt_1ms":4}
I20260812 06:16:44.393208  8452 maintenance_manager.cc:419] P 8861b0bf87134f88b5b93aec1aa63d3a: Scheduling MajorDeltaCompactionOp(835731265bd54d31b267935835cd167d): perf score=1.000000
I20260812 06:16:44.538997  8356 maintenance_manager.cc:643] P 8861b0bf87134f88b5b93aec1aa63d3a: MajorDeltaCompactionOp(835731265bd54d31b267935835cd167d) complete. Timing: real 0.146s	user 0.117s	sys 0.028s Metrics: {"cfile_cache_miss":522,"cfile_cache_miss_bytes":24405442,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":852,"lbm_read_time_us":10390,"lbm_reads_lt_1ms":550,"lbm_write_time_us":26971,"lbm_writes_lt_1ms":533,"mutex_wait_us":69,"peak_mem_usage":61665166,"reinsert_count":0,"thread_start_us":349,"threads_started":5,"update_count":2450}
I20260812 06:16:44.539779  8452 maintenance_manager.cc:419] P 8861b0bf87134f88b5b93aec1aa63d3a: Scheduling FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d): perf score=14.095187
I20260812 06:16:44.587073  8356 maintenance_manager.cc:643] P 8861b0bf87134f88b5b93aec1aa63d3a: FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d) complete. Timing: real 0.047s	user 0.028s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21359,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:44.587571  8452 maintenance_manager.cc:419] P 8861b0bf87134f88b5b93aec1aa63d3a: Scheduling FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d): perf score=2.188937
I20260812 06:16:44.598510  8356 maintenance_manager.cc:643] P 8861b0bf87134f88b5b93aec1aa63d3a: FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4221,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:44.598979  8452 maintenance_manager.cc:419] P 8861b0bf87134f88b5b93aec1aa63d3a: Scheduling MajorDeltaCompactionOp(835731265bd54d31b267935835cd167d): perf score=1.000000
I20260812 06:16:44.762646  8356 maintenance_manager.cc:643] P 8861b0bf87134f88b5b93aec1aa63d3a: MajorDeltaCompactionOp(835731265bd54d31b267935835cd167d) complete. Timing: real 0.164s	user 0.106s	sys 0.046s 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":249,"lbm_read_time_us":11089,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30836,"lbm_writes_lt_1ms":543,"mutex_wait_us":60,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:16:44.763113  8452 maintenance_manager.cc:419] P 8861b0bf87134f88b5b93aec1aa63d3a: Scheduling FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d): perf score=14.095187
I20260812 06:16:44.814222  8356 maintenance_manager.cc:643] P 8861b0bf87134f88b5b93aec1aa63d3a: FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d) complete. Timing: real 0.051s	user 0.025s	sys 0.017s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19390,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:44.814703  8452 maintenance_manager.cc:419] P 8861b0bf87134f88b5b93aec1aa63d3a: Scheduling FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d): perf score=2.188937
I20260812 06:16:44.825630  8356 maintenance_manager.cc:643] P 8861b0bf87134f88b5b93aec1aa63d3a: FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4066,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:44.826139  8452 maintenance_manager.cc:419] P 8861b0bf87134f88b5b93aec1aa63d3a: Scheduling MajorDeltaCompactionOp(835731265bd54d31b267935835cd167d): perf score=1.000000
I20260812 06:16:44.992425  8356 maintenance_manager.cc:643] P 8861b0bf87134f88b5b93aec1aa63d3a: MajorDeltaCompactionOp(835731265bd54d31b267935835cd167d) complete. Timing: real 0.166s	user 0.096s	sys 0.057s 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":272,"lbm_read_time_us":10103,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30993,"lbm_writes_lt_1ms":543,"mutex_wait_us":37,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11648,"update_count":2500}
I20260812 06:16:44.993139  8452 maintenance_manager.cc:419] P 8861b0bf87134f88b5b93aec1aa63d3a: Scheduling FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d): perf score=14.095187
I20260812 06:16:45.048594  8356 maintenance_manager.cc:643] P 8861b0bf87134f88b5b93aec1aa63d3a: FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d) complete. Timing: real 0.055s	user 0.029s	sys 0.019s Metrics: {"bytes_written":16409897,"delete_count":0,"lbm_write_time_us":21853,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:45.049089  8452 maintenance_manager.cc:419] P 8861b0bf87134f88b5b93aec1aa63d3a: Scheduling FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d): perf score=2.188937
I20260812 06:16:45.059821  8356 maintenance_manager.cc:643] P 8861b0bf87134f88b5b93aec1aa63d3a: FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d) complete. Timing: real 0.011s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3975,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:45.060573  8452 maintenance_manager.cc:419] P 8861b0bf87134f88b5b93aec1aa63d3a: Scheduling MajorDeltaCompactionOp(835731265bd54d31b267935835cd167d): perf score=1.000000
I20260812 06:16:45.244773  8356 maintenance_manager.cc:643] P 8861b0bf87134f88b5b93aec1aa63d3a: MajorDeltaCompactionOp(835731265bd54d31b267935835cd167d) complete. Timing: real 0.184s	user 0.128s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815679,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":188,"lbm_read_time_us":13601,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28566,"lbm_writes_lt_1ms":543,"mutex_wait_us":37,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":17536,"update_count":2500}
I20260812 06:16:45.245466  8452 maintenance_manager.cc:419] P 8861b0bf87134f88b5b93aec1aa63d3a: Scheduling FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d): perf score=14.095187
I20260812 06:16:45.295408  8356 maintenance_manager.cc:643] P 8861b0bf87134f88b5b93aec1aa63d3a: FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d) complete. Timing: real 0.050s	user 0.024s	sys 0.020s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21171,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:45.295871  8452 maintenance_manager.cc:419] P 8861b0bf87134f88b5b93aec1aa63d3a: Scheduling MajorDeltaCompactionOp(835731265bd54d31b267935835cd167d): perf score=1.000000
I20260812 06:16:45.439662  8356 maintenance_manager.cc:643] P 8861b0bf87134f88b5b93aec1aa63d3a: MajorDeltaCompactionOp(835731265bd54d31b267935835cd167d) complete. Timing: real 0.144s	user 0.101s	sys 0.037s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713153,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":520,"lbm_read_time_us":9179,"lbm_reads_lt_1ms":463,"lbm_write_time_us":23396,"lbm_writes_lt_1ms":443,"mutex_wait_us":212,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4096,"update_count":2000}
I20260812 06:16:45.440193  8452 maintenance_manager.cc:419] P 8861b0bf87134f88b5b93aec1aa63d3a: Scheduling FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d): perf score=14.095187
I20260812 06:16:45.500967  8356 maintenance_manager.cc:643] P 8861b0bf87134f88b5b93aec1aa63d3a: FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d) complete. Timing: real 0.061s	user 0.044s	sys 0.012s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":25669,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:45.501495  8452 maintenance_manager.cc:419] P 8861b0bf87134f88b5b93aec1aa63d3a: Scheduling FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d): perf score=2.188937
I20260812 06:16:45.512867  8356 maintenance_manager.cc:643] P 8861b0bf87134f88b5b93aec1aa63d3a: FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3984,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:45.513350  8452 maintenance_manager.cc:419] P 8861b0bf87134f88b5b93aec1aa63d3a: Scheduling FlushMRSOp(835731265bd54d31b267935835cd167d): perf score=1.000000
I20260812 06:16:45.552196  8356 maintenance_manager.cc:643] P 8861b0bf87134f88b5b93aec1aa63d3a: FlushMRSOp(835731265bd54d31b267935835cd167d) complete. Timing: real 0.039s	user 0.037s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":65,"dirs.run_cpu_time_us":196,"dirs.run_wall_time_us":1351,"drs_written":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1845,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:16:45.552928  8452 maintenance_manager.cc:419] P 8861b0bf87134f88b5b93aec1aa63d3a: Scheduling LogGCOp(835731265bd54d31b267935835cd167d): free 112239255 bytes of WAL
I20260812 06:16:45.553189  8356 log_reader.cc:385] T 835731265bd54d31b267935835cd167d: removed 11 log segments from log reader
I20260812 06:16:45.553270  8356 log.cc:1079] T 835731265bd54d31b267935835cd167d P 8861b0bf87134f88b5b93aec1aa63d3a: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/835731265bd54d31b267935835cd167d/wal-000000003 (ops 12-16)
I20260812 06:16:45.553325  8356 log.cc:1079] T 835731265bd54d31b267935835cd167d P 8861b0bf87134f88b5b93aec1aa63d3a: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/835731265bd54d31b267935835cd167d/wal-000000004 (ops 17-21)
I20260812 06:16:45.553364  8356 log.cc:1079] T 835731265bd54d31b267935835cd167d P 8861b0bf87134f88b5b93aec1aa63d3a: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/835731265bd54d31b267935835cd167d/wal-000000005 (ops 22-26)
I20260812 06:16:45.553403  8356 log.cc:1079] T 835731265bd54d31b267935835cd167d P 8861b0bf87134f88b5b93aec1aa63d3a: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/835731265bd54d31b267935835cd167d/wal-000000006 (ops 27-30)
I20260812 06:16:45.553442  8356 log.cc:1079] T 835731265bd54d31b267935835cd167d P 8861b0bf87134f88b5b93aec1aa63d3a: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/835731265bd54d31b267935835cd167d/wal-000000007 (ops 31-35)
I20260812 06:16:45.553483  8356 log.cc:1079] T 835731265bd54d31b267935835cd167d P 8861b0bf87134f88b5b93aec1aa63d3a: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/835731265bd54d31b267935835cd167d/wal-000000008 (ops 36-40)
I20260812 06:16:45.553521  8356 log.cc:1079] T 835731265bd54d31b267935835cd167d P 8861b0bf87134f88b5b93aec1aa63d3a: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/835731265bd54d31b267935835cd167d/wal-000000009 (ops 41-45)
I20260812 06:16:45.553557  8356 log.cc:1079] T 835731265bd54d31b267935835cd167d P 8861b0bf87134f88b5b93aec1aa63d3a: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/835731265bd54d31b267935835cd167d/wal-000000010 (ops 46-50)
I20260812 06:16:45.553596  8356 log.cc:1079] T 835731265bd54d31b267935835cd167d P 8861b0bf87134f88b5b93aec1aa63d3a: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/835731265bd54d31b267935835cd167d/wal-000000011 (ops 51-55)
I20260812 06:16:45.553635  8356 log.cc:1079] T 835731265bd54d31b267935835cd167d P 8861b0bf87134f88b5b93aec1aa63d3a: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/835731265bd54d31b267935835cd167d/wal-000000012 (ops 56-60)
I20260812 06:16:45.553674  8356 log.cc:1079] T 835731265bd54d31b267935835cd167d P 8861b0bf87134f88b5b93aec1aa63d3a: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/835731265bd54d31b267935835cd167d/wal-000000013 (ops 61-65)
I20260812 06:16:45.577873  8356 maintenance_manager.cc:643] P 8861b0bf87134f88b5b93aec1aa63d3a: LogGCOp(835731265bd54d31b267935835cd167d) complete. Timing: real 0.025s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:16:45.578382  8452 maintenance_manager.cc:419] P 8861b0bf87134f88b5b93aec1aa63d3a: Scheduling UndoDeltaBlockGCOp(835731265bd54d31b267935835cd167d): 447 bytes on disk
I20260812 06:16:45.579056  8356 maintenance_manager.cc:643] P 8861b0bf87134f88b5b93aec1aa63d3a: UndoDeltaBlockGCOp(835731265bd54d31b267935835cd167d) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":118,"lbm_reads_lt_1ms":4}
I20260812 06:16:45.579581  8452 maintenance_manager.cc:419] P 8861b0bf87134f88b5b93aec1aa63d3a: Scheduling FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d): perf score=3.181125
I20260812 06:16:45.598498  8356 maintenance_manager.cc:643] P 8861b0bf87134f88b5b93aec1aa63d3a: FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d) complete. Timing: real 0.019s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":4759,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:45.598986  8452 maintenance_manager.cc:419] P 8861b0bf87134f88b5b93aec1aa63d3a: Scheduling LogGCOp(835731265bd54d31b267935835cd167d): free 12017983 bytes of WAL
I20260812 06:16:45.599192  8356 log_reader.cc:385] T 835731265bd54d31b267935835cd167d: removed 1 log segments from log reader
I20260812 06:16:45.599238  8356 log.cc:1079] T 835731265bd54d31b267935835cd167d P 8861b0bf87134f88b5b93aec1aa63d3a: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/835731265bd54d31b267935835cd167d/wal-000000014 (ops 66-70)
I20260812 06:16:45.601703  8356 maintenance_manager.cc:643] P 8861b0bf87134f88b5b93aec1aa63d3a: LogGCOp(835731265bd54d31b267935835cd167d) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:16:45.602015  8452 maintenance_manager.cc:419] P 8861b0bf87134f88b5b93aec1aa63d3a: Scheduling FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d): perf score=2.188937
I20260812 06:16:45.612701  8356 maintenance_manager.cc:643] P 8861b0bf87134f88b5b93aec1aa63d3a: FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3770,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:45.613567  8452 maintenance_manager.cc:419] P 8861b0bf87134f88b5b93aec1aa63d3a: Scheduling MajorDeltaCompactionOp(835731265bd54d31b267935835cd167d): perf score=1.000000
I20260812 06:16:45.866132  8356 maintenance_manager.cc:643] P 8861b0bf87134f88b5b93aec1aa63d3a: MajorDeltaCompactionOp(835731265bd54d31b267935835cd167d) complete. Timing: real 0.252s	user 0.153s	sys 0.084s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020736,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1624,"lbm_read_time_us":15957,"lbm_reads_lt_1ms":774,"lbm_write_time_us":39656,"lbm_writes_lt_1ms":743,"mutex_wait_us":406,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":3978368,"thread_start_us":102,"threads_started":1,"update_count":3500}
I20260812 06:16:45.866906  8452 maintenance_manager.cc:419] P 8861b0bf87134f88b5b93aec1aa63d3a: Scheduling FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d): perf score=18.063937
I20260812 06:16:45.932066  8356 maintenance_manager.cc:643] P 8861b0bf87134f88b5b93aec1aa63d3a: FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d) complete. Timing: real 0.065s	user 0.028s	sys 0.018s Metrics: {"bytes_written":20512318,"delete_count":0,"lbm_write_time_us":23010,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:16:45.932556  8452 maintenance_manager.cc:419] P 8861b0bf87134f88b5b93aec1aa63d3a: Scheduling FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d): perf score=2.188937
I20260812 06:16:45.944375  8356 maintenance_manager.cc:643] P 8861b0bf87134f88b5b93aec1aa63d3a: FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d) complete. Timing: real 0.012s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4146,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:45.945010  8452 maintenance_manager.cc:419] P 8861b0bf87134f88b5b93aec1aa63d3a: Scheduling MajorDeltaCompactionOp(835731265bd54d31b267935835cd167d): perf score=1.000000
I20260812 06:16:46.141822  8356 maintenance_manager.cc:643] P 8861b0bf87134f88b5b93aec1aa63d3a: MajorDeltaCompactionOp(835731265bd54d31b267935835cd167d) complete. Timing: real 0.197s	user 0.132s	sys 0.064s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918100,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":536,"lbm_read_time_us":13451,"lbm_reads_lt_1ms":672,"lbm_write_time_us":33337,"lbm_writes_lt_1ms":643,"mutex_wait_us":24,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":11392,"update_count":3000}
I20260812 06:16:46.145578  8452 maintenance_manager.cc:419] P 8861b0bf87134f88b5b93aec1aa63d3a: Scheduling FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d): perf score=14.095187
I20260812 06:16:46.198146  8356 maintenance_manager.cc:643] P 8861b0bf87134f88b5b93aec1aa63d3a: FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d) complete. Timing: real 0.052s	user 0.030s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23129,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:46.198755  8452 maintenance_manager.cc:419] P 8861b0bf87134f88b5b93aec1aa63d3a: Scheduling FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d): perf score=2.188937
I20260812 06:16:46.213985  8356 maintenance_manager.cc:643] P 8861b0bf87134f88b5b93aec1aa63d3a: FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5191,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:46.214514  8452 maintenance_manager.cc:419] P 8861b0bf87134f88b5b93aec1aa63d3a: Scheduling FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d): perf score=2.188937
I20260812 06:16:46.230062  8356 maintenance_manager.cc:643] P 8861b0bf87134f88b5b93aec1aa63d3a: FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d) complete. Timing: real 0.015s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6084,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:46.230594  8452 maintenance_manager.cc:419] P 8861b0bf87134f88b5b93aec1aa63d3a: Scheduling MajorDeltaCompactionOp(835731265bd54d31b267935835cd167d): perf score=1.000000
I20260812 06:16:46.447723  8356 maintenance_manager.cc:643] P 8861b0bf87134f88b5b93aec1aa63d3a: MajorDeltaCompactionOp(835731265bd54d31b267935835cd167d) complete. Timing: real 0.217s	user 0.133s	sys 0.080s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918213,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":350,"lbm_read_time_us":14833,"lbm_reads_lt_1ms":673,"lbm_write_time_us":37064,"lbm_writes_lt_1ms":643,"mutex_wait_us":40,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":3000}
I20260812 06:16:46.448472  8452 maintenance_manager.cc:419] P 8861b0bf87134f88b5b93aec1aa63d3a: Scheduling FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d): perf score=16.079562
I20260812 06:16:46.507236  8356 maintenance_manager.cc:643] P 8861b0bf87134f88b5b93aec1aa63d3a: FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d) complete. Timing: real 0.059s	user 0.031s	sys 0.021s Metrics: {"bytes_written":18338035,"delete_count":0,"lbm_write_time_us":24718,"lbm_writes_lt_1ms":450,"reinsert_count":0,"update_count":2235}
I20260812 06:16:46.507786  8452 maintenance_manager.cc:419] P 8861b0bf87134f88b5b93aec1aa63d3a: Scheduling FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d): perf score=1.196750
I20260812 06:16:46.518283  8356 maintenance_manager.cc:643] P 8861b0bf87134f88b5b93aec1aa63d3a: FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d) complete. Timing: real 0.010s	user 0.000s	sys 0.006s Metrics: {"bytes_written":2584734,"delete_count":0,"lbm_write_time_us":2637,"lbm_writes_lt_1ms":66,"reinsert_count":0,"update_count":315}
I20260812 06:16:46.518718  8452 maintenance_manager.cc:419] P 8861b0bf87134f88b5b93aec1aa63d3a: Scheduling FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d): perf score=2.188937
I20260812 06:16:46.528110  8356 maintenance_manager.cc:643] P 8861b0bf87134f88b5b93aec1aa63d3a: FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3672,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:46.528653  8452 maintenance_manager.cc:419] P 8861b0bf87134f88b5b93aec1aa63d3a: Scheduling MajorDeltaCompactionOp(835731265bd54d31b267935835cd167d): perf score=1.000000
I20260812 06:16:46.728761  8356 maintenance_manager.cc:643] P 8861b0bf87134f88b5b93aec1aa63d3a: MajorDeltaCompactionOp(835731265bd54d31b267935835cd167d) complete. Timing: real 0.200s	user 0.143s	sys 0.054s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918169,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":201,"lbm_read_time_us":13651,"lbm_reads_lt_1ms":673,"lbm_write_time_us":34250,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":642,"mutex_wait_us":30,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":14464,"update_count":3000}
I20260812 06:16:46.729902  8452 maintenance_manager.cc:419] P 8861b0bf87134f88b5b93aec1aa63d3a: Scheduling FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d): perf score=16.079562
I20260812 06:16:46.800067  8356 maintenance_manager.cc:643] P 8861b0bf87134f88b5b93aec1aa63d3a: FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d) complete. Timing: real 0.070s	user 0.036s	sys 0.016s Metrics: {"bytes_written":17763699,"delete_count":0,"lbm_write_time_us":24359,"lbm_writes_lt_1ms":436,"reinsert_count":0,"update_count":2165}
I20260812 06:16:46.800622  8452 maintenance_manager.cc:419] P 8861b0bf87134f88b5b93aec1aa63d3a: Scheduling FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d): perf score=5.165500
I20260812 06:16:46.824813  8356 maintenance_manager.cc:643] P 8861b0bf87134f88b5b93aec1aa63d3a: FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d) complete. Timing: real 0.024s	user 0.006s	sys 0.017s Metrics: {"bytes_written":6851289,"delete_count":0,"lbm_write_time_us":9942,"lbm_writes_lt_1ms":170,"reinsert_count":0,"update_count":835}
I20260812 06:16:46.825414  8452 maintenance_manager.cc:419] P 8861b0bf87134f88b5b93aec1aa63d3a: Scheduling MajorDeltaCompactionOp(835731265bd54d31b267935835cd167d): perf score=1.000000
I20260812 06:16:47.046396  8356 maintenance_manager.cc:643] P 8861b0bf87134f88b5b93aec1aa63d3a: MajorDeltaCompactionOp(835731265bd54d31b267935835cd167d) complete. Timing: real 0.221s	user 0.154s	sys 0.057s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918105,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":792,"lbm_read_time_us":14246,"lbm_reads_lt_1ms":672,"lbm_write_time_us":33760,"lbm_writes_lt_1ms":643,"mutex_wait_us":318,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":6656,"update_count":3000}
I20260812 06:16:47.047041  8452 maintenance_manager.cc:419] P 8861b0bf87134f88b5b93aec1aa63d3a: Scheduling FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d): perf score=18.063937
I20260812 06:16:47.110495  8356 maintenance_manager.cc:643] P 8861b0bf87134f88b5b93aec1aa63d3a: FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d) complete. Timing: real 0.063s	user 0.049s	sys 0.008s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":26794,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":502,"reinsert_count":0,"update_count":2500}
I20260812 06:16:47.110961  8452 maintenance_manager.cc:419] P 8861b0bf87134f88b5b93aec1aa63d3a: Scheduling FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d): perf score=2.188937
I20260812 06:16:47.121959  8356 maintenance_manager.cc:643] P 8861b0bf87134f88b5b93aec1aa63d3a: FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3907,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:47.122694  8452 maintenance_manager.cc:419] P 8861b0bf87134f88b5b93aec1aa63d3a: Scheduling FlushMRSOp(835731265bd54d31b267935835cd167d): perf score=1.000000
I20260812 06:16:47.158468  8356 maintenance_manager.cc:643] P 8861b0bf87134f88b5b93aec1aa63d3a: FlushMRSOp(835731265bd54d31b267935835cd167d) complete. Timing: real 0.036s	user 0.031s	sys 0.003s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":65,"dirs.run_cpu_time_us":220,"dirs.run_wall_time_us":1469,"drs_written":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2080,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:16:47.159085  8452 maintenance_manager.cc:419] P 8861b0bf87134f88b5b93aec1aa63d3a: Scheduling LogGCOp(835731265bd54d31b267935835cd167d): free 121006451 bytes of WAL
I20260812 06:16:47.159317  8356 log_reader.cc:385] T 835731265bd54d31b267935835cd167d: removed 12 log segments from log reader
I20260812 06:16:47.159364  8356 log.cc:1079] T 835731265bd54d31b267935835cd167d P 8861b0bf87134f88b5b93aec1aa63d3a: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/835731265bd54d31b267935835cd167d/wal-000000015 (ops 71-75)
I20260812 06:16:47.159392  8356 log.cc:1079] T 835731265bd54d31b267935835cd167d P 8861b0bf87134f88b5b93aec1aa63d3a: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/835731265bd54d31b267935835cd167d/wal-000000016 (ops 76-80)
I20260812 06:16:47.159448  8356 log.cc:1079] T 835731265bd54d31b267935835cd167d P 8861b0bf87134f88b5b93aec1aa63d3a: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/835731265bd54d31b267935835cd167d/wal-000000017 (ops 81-85)
I20260812 06:16:47.159487  8356 log.cc:1079] T 835731265bd54d31b267935835cd167d P 8861b0bf87134f88b5b93aec1aa63d3a: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/835731265bd54d31b267935835cd167d/wal-000000018 (ops 86-90)
I20260812 06:16:47.159528  8356 log.cc:1079] T 835731265bd54d31b267935835cd167d P 8861b0bf87134f88b5b93aec1aa63d3a: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/835731265bd54d31b267935835cd167d/wal-000000019 (ops 91-95)
I20260812 06:16:47.159552  8356 log.cc:1079] T 835731265bd54d31b267935835cd167d P 8861b0bf87134f88b5b93aec1aa63d3a: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/835731265bd54d31b267935835cd167d/wal-000000020 (ops 96-100)
I20260812 06:16:47.159608  8356 log.cc:1079] T 835731265bd54d31b267935835cd167d P 8861b0bf87134f88b5b93aec1aa63d3a: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/835731265bd54d31b267935835cd167d/wal-000000021 (ops 101-104)
I20260812 06:16:47.159648  8356 log.cc:1079] T 835731265bd54d31b267935835cd167d P 8861b0bf87134f88b5b93aec1aa63d3a: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/835731265bd54d31b267935835cd167d/wal-000000022 (ops 105-109)
I20260812 06:16:47.159693  8356 log.cc:1079] T 835731265bd54d31b267935835cd167d P 8861b0bf87134f88b5b93aec1aa63d3a: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/835731265bd54d31b267935835cd167d/wal-000000023 (ops 110-114)
I20260812 06:16:47.159739  8356 log.cc:1079] T 835731265bd54d31b267935835cd167d P 8861b0bf87134f88b5b93aec1aa63d3a: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/835731265bd54d31b267935835cd167d/wal-000000024 (ops 115-119)
I20260812 06:16:47.159786  8356 log.cc:1079] T 835731265bd54d31b267935835cd167d P 8861b0bf87134f88b5b93aec1aa63d3a: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/835731265bd54d31b267935835cd167d/wal-000000025 (ops 120-124)
I20260812 06:16:47.159830  8356 log.cc:1079] T 835731265bd54d31b267935835cd167d P 8861b0bf87134f88b5b93aec1aa63d3a: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/835731265bd54d31b267935835cd167d/wal-000000026 (ops 125-129)
I20260812 06:16:47.185937  8356 maintenance_manager.cc:643] P 8861b0bf87134f88b5b93aec1aa63d3a: LogGCOp(835731265bd54d31b267935835cd167d) complete. Timing: real 0.027s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:16:47.186543  8452 maintenance_manager.cc:419] P 8861b0bf87134f88b5b93aec1aa63d3a: Scheduling FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d): perf score=3.181125
I20260812 06:16:47.199669  8356 maintenance_manager.cc:643] P 8861b0bf87134f88b5b93aec1aa63d3a: FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d) complete. Timing: real 0.013s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4841097,"delete_count":0,"lbm_write_time_us":5244,"lbm_writes_lt_1ms":121,"reinsert_count":0,"update_count":590}
I20260812 06:16:47.200137  8452 maintenance_manager.cc:419] P 8861b0bf87134f88b5b93aec1aa63d3a: Scheduling LogGCOp(835731265bd54d31b267935835cd167d): free 12017954 bytes of WAL
I20260812 06:16:47.200390  8356 log_reader.cc:385] T 835731265bd54d31b267935835cd167d: removed 1 log segments from log reader
I20260812 06:16:47.200450  8356 log.cc:1079] T 835731265bd54d31b267935835cd167d P 8861b0bf87134f88b5b93aec1aa63d3a: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/835731265bd54d31b267935835cd167d/wal-000000027 (ops 130-134)
I20260812 06:16:47.203372  8356 maintenance_manager.cc:643] P 8861b0bf87134f88b5b93aec1aa63d3a: LogGCOp(835731265bd54d31b267935835cd167d) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:16:47.203665  8452 maintenance_manager.cc:419] P 8861b0bf87134f88b5b93aec1aa63d3a: Scheduling UndoDeltaBlockGCOp(835731265bd54d31b267935835cd167d): 492 bytes on disk
I20260812 06:16:47.204121  8356 maintenance_manager.cc:643] P 8861b0bf87134f88b5b93aec1aa63d3a: UndoDeltaBlockGCOp(835731265bd54d31b267935835cd167d) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":75,"lbm_reads_lt_1ms":4}
I20260812 06:16:47.204725  8452 maintenance_manager.cc:419] P 8861b0bf87134f88b5b93aec1aa63d3a: Scheduling FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d): perf score=2.188937
I20260812 06:16:47.214634  8356 maintenance_manager.cc:643] P 8861b0bf87134f88b5b93aec1aa63d3a: FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d) complete. Timing: real 0.010s	user 0.002s	sys 0.005s Metrics: {"bytes_written":3364205,"delete_count":0,"lbm_write_time_us":3195,"lbm_writes_lt_1ms":85,"reinsert_count":0,"update_count":410}
I20260812 06:16:47.215224  8452 maintenance_manager.cc:419] P 8861b0bf87134f88b5b93aec1aa63d3a: Scheduling MajorDeltaCompactionOp(835731265bd54d31b267935835cd167d): perf score=1.000000
I20260812 06:16:47.467612  8356 maintenance_manager.cc:643] P 8861b0bf87134f88b5b93aec1aa63d3a: MajorDeltaCompactionOp(835731265bd54d31b267935835cd167d) complete. Timing: real 0.252s	user 0.172s	sys 0.080s Metrics: {"cfile_cache_miss":834,"cfile_cache_miss_bytes":37123145,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":796,"lbm_read_time_us":18886,"lbm_reads_lt_1ms":874,"lbm_write_time_us":45240,"lbm_writes_lt_1ms":843,"mutex_wait_us":28,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":4736,"thread_start_us":100,"threads_started":1,"update_count":4000}
I20260812 06:16:47.468361  8452 maintenance_manager.cc:419] P 8861b0bf87134f88b5b93aec1aa63d3a: Scheduling FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d): perf score=18.063937
I20260812 06:16:47.544075  8356 maintenance_manager.cc:643] P 8861b0bf87134f88b5b93aec1aa63d3a: FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d) complete. Timing: real 0.075s	user 0.017s	sys 0.051s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":31202,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":502,"reinsert_count":0,"update_count":2500}
I20260812 06:16:47.544827  8452 maintenance_manager.cc:419] P 8861b0bf87134f88b5b93aec1aa63d3a: Scheduling FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d): perf score=4.173312
I20260812 06:16:47.562634  8356 maintenance_manager.cc:643] P 8861b0bf87134f88b5b93aec1aa63d3a: FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d) complete. Timing: real 0.018s	user 0.007s	sys 0.009s Metrics: {"bytes_written":5661587,"delete_count":0,"lbm_write_time_us":7477,"lbm_writes_lt_1ms":141,"reinsert_count":0,"update_count":690}
I20260812 06:16:47.563072  8452 maintenance_manager.cc:419] P 8861b0bf87134f88b5b93aec1aa63d3a: Scheduling FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d): perf score=1.196750
I20260812 06:16:47.571000  8356 maintenance_manager.cc:643] P 8861b0bf87134f88b5b93aec1aa63d3a: FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d) complete. Timing: real 0.008s	user 0.000s	sys 0.006s Metrics: {"bytes_written":2543704,"delete_count":0,"lbm_write_time_us":2638,"lbm_writes_lt_1ms":65,"reinsert_count":0,"update_count":310}
I20260812 06:16:47.571449  8452 maintenance_manager.cc:419] P 8861b0bf87134f88b5b93aec1aa63d3a: Scheduling MajorDeltaCompactionOp(835731265bd54d31b267935835cd167d): perf score=1.000000
I20260812 06:16:47.756640  8356 maintenance_manager.cc:643] P 8861b0bf87134f88b5b93aec1aa63d3a: MajorDeltaCompactionOp(835731265bd54d31b267935835cd167d) complete. Timing: real 0.185s	user 0.120s	sys 0.064s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":33020595,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1003,"lbm_read_time_us":12723,"lbm_reads_lt_1ms":773,"lbm_write_time_us":39412,"lbm_writes_lt_1ms":743,"mutex_wait_us":54,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":26240,"update_count":3500}
I20260812 06:16:47.757452  8452 maintenance_manager.cc:419] P 8861b0bf87134f88b5b93aec1aa63d3a: Scheduling FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d): perf score=14.095187
I20260812 06:16:47.800292  8356 maintenance_manager.cc:643] P 8861b0bf87134f88b5b93aec1aa63d3a: FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d) complete. Timing: real 0.043s	user 0.032s	sys 0.008s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":19038,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:47.800824  8452 maintenance_manager.cc:419] P 8861b0bf87134f88b5b93aec1aa63d3a: Scheduling FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d): perf score=2.188937
I20260812 06:16:47.812003  8356 maintenance_manager.cc:643] P 8861b0bf87134f88b5b93aec1aa63d3a: FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3923,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:47.812610  8452 maintenance_manager.cc:419] P 8861b0bf87134f88b5b93aec1aa63d3a: Scheduling MajorDeltaCompactionOp(835731265bd54d31b267935835cd167d): perf score=1.000000
I20260812 06:16:47.962225  8356 maintenance_manager.cc:643] P 8861b0bf87134f88b5b93aec1aa63d3a: MajorDeltaCompactionOp(835731265bd54d31b267935835cd167d) complete. Timing: real 0.149s	user 0.113s	sys 0.034s 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":182,"lbm_read_time_us":9308,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28877,"lbm_writes_lt_1ms":543,"mutex_wait_us":25,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":2500}
I20260812 06:16:47.962949  8452 maintenance_manager.cc:419] P 8861b0bf87134f88b5b93aec1aa63d3a: Scheduling FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d): perf score=12.110812
I20260812 06:16:48.002799  8356 maintenance_manager.cc:643] P 8861b0bf87134f88b5b93aec1aa63d3a: FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d) complete. Timing: real 0.040s	user 0.011s	sys 0.026s Metrics: {"bytes_written":13948451,"delete_count":0,"lbm_write_time_us":16813,"lbm_writes_lt_1ms":343,"reinsert_count":0,"update_count":1700}
I20260812 06:16:48.003237  8452 maintenance_manager.cc:419] P 8861b0bf87134f88b5b93aec1aa63d3a: Scheduling FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d): perf score=1.196750
I20260812 06:16:48.023269  8356 maintenance_manager.cc:643] P 8861b0bf87134f88b5b93aec1aa63d3a: FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d) complete. Timing: real 0.020s	user 0.000s	sys 0.006s Metrics: {"bytes_written":2461654,"delete_count":0,"lbm_write_time_us":2529,"lbm_writes_lt_1ms":63,"reinsert_count":0,"update_count":300}
I20260812 06:16:48.023741  8452 maintenance_manager.cc:419] P 8861b0bf87134f88b5b93aec1aa63d3a: Scheduling FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d): perf score=2.188937
I20260812 06:16:48.033360  8356 maintenance_manager.cc:643] P 8861b0bf87134f88b5b93aec1aa63d3a: FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3670,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:48.033761  8452 maintenance_manager.cc:419] P 8861b0bf87134f88b5b93aec1aa63d3a: Scheduling MajorDeltaCompactionOp(835731265bd54d31b267935835cd167d): perf score=1.000000
I20260812 06:16:48.222118  8356 maintenance_manager.cc:643] P 8861b0bf87134f88b5b93aec1aa63d3a: MajorDeltaCompactionOp(835731265bd54d31b267935835cd167d) complete. Timing: real 0.188s	user 0.099s	sys 0.079s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815759,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":154,"lbm_read_time_us":13032,"lbm_reads_lt_1ms":573,"lbm_write_time_us":31385,"lbm_writes_lt_1ms":543,"mutex_wait_us":24,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":19456,"update_count":2500}
I20260812 06:16:48.222808  8452 maintenance_manager.cc:419] P 8861b0bf87134f88b5b93aec1aa63d3a: Scheduling FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d): perf score=14.095187
I20260812 06:16:48.266093  8356 maintenance_manager.cc:643] P 8861b0bf87134f88b5b93aec1aa63d3a: FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d) complete. Timing: real 0.043s	user 0.019s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17366,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:48.266835  8452 maintenance_manager.cc:419] P 8861b0bf87134f88b5b93aec1aa63d3a: Scheduling MajorDeltaCompactionOp(835731265bd54d31b267935835cd167d): perf score=1.000000
I20260812 06:16:48.421490  8356 maintenance_manager.cc:643] P 8861b0bf87134f88b5b93aec1aa63d3a: MajorDeltaCompactionOp(835731265bd54d31b267935835cd167d) complete. Timing: real 0.154s	user 0.113s	sys 0.035s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713152,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":243,"lbm_read_time_us":9094,"lbm_reads_lt_1ms":463,"lbm_write_time_us":26065,"lbm_writes_lt_1ms":443,"mutex_wait_us":44,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7168,"update_count":2000}
I20260812 06:16:48.422304  8452 maintenance_manager.cc:419] P 8861b0bf87134f88b5b93aec1aa63d3a: Scheduling FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d): perf score=14.095187
I20260812 06:16:48.472201  8356 maintenance_manager.cc:643] P 8861b0bf87134f88b5b93aec1aa63d3a: FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d) complete. Timing: real 0.050s	user 0.036s	sys 0.008s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":20702,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:48.472781  8452 maintenance_manager.cc:419] P 8861b0bf87134f88b5b93aec1aa63d3a: Scheduling FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d): perf score=2.188937
I20260812 06:16:48.483590  8356 maintenance_manager.cc:643] P 8861b0bf87134f88b5b93aec1aa63d3a: FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3878,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:48.484242  8452 maintenance_manager.cc:419] P 8861b0bf87134f88b5b93aec1aa63d3a: Scheduling FlushMRSOp(835731265bd54d31b267935835cd167d): perf score=1.000000
I20260812 06:16:48.509636  8356 maintenance_manager.cc:643] P 8861b0bf87134f88b5b93aec1aa63d3a: FlushMRSOp(835731265bd54d31b267935835cd167d) complete. Timing: real 0.025s	user 0.018s	sys 0.005s Metrics: {"bytes_written":1152512,"cfile_init":1,"dirs.queue_time_us":71,"dirs.run_cpu_time_us":209,"dirs.run_wall_time_us":1295,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1558,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:16:48.510926  8452 maintenance_manager.cc:419] P 8861b0bf87134f88b5b93aec1aa63d3a: Scheduling FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d): perf score=2.188937
I20260812 06:16:48.526212  8356 maintenance_manager.cc:643] P 8861b0bf87134f88b5b93aec1aa63d3a: FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6278,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:48.526747  8452 maintenance_manager.cc:419] P 8861b0bf87134f88b5b93aec1aa63d3a: Scheduling LogGCOp(835731265bd54d31b267935835cd167d): free 108535706 bytes of WAL
I20260812 06:16:48.527081  8356 log_reader.cc:385] T 835731265bd54d31b267935835cd167d: removed 11 log segments from log reader
I20260812 06:16:48.527170  8356 log.cc:1079] T 835731265bd54d31b267935835cd167d P 8861b0bf87134f88b5b93aec1aa63d3a: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/835731265bd54d31b267935835cd167d/wal-000000028 (ops 135-139)
I20260812 06:16:48.527220  8356 log.cc:1079] T 835731265bd54d31b267935835cd167d P 8861b0bf87134f88b5b93aec1aa63d3a: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/835731265bd54d31b267935835cd167d/wal-000000029 (ops 140-144)
I20260812 06:16:48.527263  8356 log.cc:1079] T 835731265bd54d31b267935835cd167d P 8861b0bf87134f88b5b93aec1aa63d3a: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/835731265bd54d31b267935835cd167d/wal-000000030 (ops 145-149)
I20260812 06:16:48.527297  8356 log.cc:1079] T 835731265bd54d31b267935835cd167d P 8861b0bf87134f88b5b93aec1aa63d3a: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/835731265bd54d31b267935835cd167d/wal-000000031 (ops 150-154)
I20260812 06:16:48.527338  8356 log.cc:1079] T 835731265bd54d31b267935835cd167d P 8861b0bf87134f88b5b93aec1aa63d3a: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/835731265bd54d31b267935835cd167d/wal-000000032 (ops 155-158)
I20260812 06:16:48.527374  8356 log.cc:1079] T 835731265bd54d31b267935835cd167d P 8861b0bf87134f88b5b93aec1aa63d3a: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/835731265bd54d31b267935835cd167d/wal-000000033 (ops 159-163)
I20260812 06:16:48.527407  8356 log.cc:1079] T 835731265bd54d31b267935835cd167d P 8861b0bf87134f88b5b93aec1aa63d3a: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/835731265bd54d31b267935835cd167d/wal-000000034 (ops 164-168)
I20260812 06:16:48.527453  8356 log.cc:1079] T 835731265bd54d31b267935835cd167d P 8861b0bf87134f88b5b93aec1aa63d3a: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/835731265bd54d31b267935835cd167d/wal-000000035 (ops 169-172)
I20260812 06:16:48.527483  8356 log.cc:1079] T 835731265bd54d31b267935835cd167d P 8861b0bf87134f88b5b93aec1aa63d3a: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/835731265bd54d31b267935835cd167d/wal-000000036 (ops 173-177)
I20260812 06:16:48.527513  8356 log.cc:1079] T 835731265bd54d31b267935835cd167d P 8861b0bf87134f88b5b93aec1aa63d3a: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/835731265bd54d31b267935835cd167d/wal-000000037 (ops 178-182)
I20260812 06:16:48.527544  8356 log.cc:1079] T 835731265bd54d31b267935835cd167d P 8861b0bf87134f88b5b93aec1aa63d3a: Deleting log segment in path: /tmp/dist-test-task262EsT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398442455-7841-0/minicluster-data/ts-0-root/wals/835731265bd54d31b267935835cd167d/wal-000000038 (ops 183-187)
I20260812 06:16:48.552752  8356 maintenance_manager.cc:643] P 8861b0bf87134f88b5b93aec1aa63d3a: LogGCOp(835731265bd54d31b267935835cd167d) complete. Timing: real 0.026s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:16:48.553364  8452 maintenance_manager.cc:419] P 8861b0bf87134f88b5b93aec1aa63d3a: Scheduling UndoDeltaBlockGCOp(835731265bd54d31b267935835cd167d): 447 bytes on disk
I20260812 06:16:48.553824  8356 maintenance_manager.cc:643] P 8861b0bf87134f88b5b93aec1aa63d3a: UndoDeltaBlockGCOp(835731265bd54d31b267935835cd167d) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":65,"lbm_reads_lt_1ms":4}
I20260812 06:16:48.554483  8452 maintenance_manager.cc:419] P 8861b0bf87134f88b5b93aec1aa63d3a: Scheduling MajorDeltaCompactionOp(835731265bd54d31b267935835cd167d): perf score=1.000000
I20260812 06:16:48.747568  8356 maintenance_manager.cc:643] P 8861b0bf87134f88b5b93aec1aa63d3a: MajorDeltaCompactionOp(835731265bd54d31b267935835cd167d) complete. Timing: real 0.193s	user 0.123s	sys 0.066s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918217,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":524,"lbm_read_time_us":14018,"lbm_reads_lt_1ms":665,"lbm_write_time_us":33413,"lbm_writes_lt_1ms":643,"mutex_wait_us":64,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":16768,"thread_start_us":98,"threads_started":1,"update_count":3000}
I20260812 06:16:48.748467  8452 maintenance_manager.cc:419] P 8861b0bf87134f88b5b93aec1aa63d3a: Scheduling FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d): perf score=15.087375
I20260812 06:16:48.799479  8356 maintenance_manager.cc:643] P 8861b0bf87134f88b5b93aec1aa63d3a: FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d) complete. Timing: real 0.051s	user 0.024s	sys 0.024s Metrics: {"bytes_written":16820146,"delete_count":0,"lbm_write_time_us":17683,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:16:48.800053  8452 maintenance_manager.cc:419] P 8861b0bf87134f88b5b93aec1aa63d3a: Scheduling FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d): perf score=2.188937
I20260812 06:16:48.822551  7841 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.772s	user 1.820s	sys 0.127s
I20260812 06:16:48.823997  8356 maintenance_manager.cc:643] P 8861b0bf87134f88b5b93aec1aa63d3a: FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d) complete. Timing: real 0.024s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4931,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:48.824505  8452 maintenance_manager.cc:419] P 8861b0bf87134f88b5b93aec1aa63d3a: Scheduling FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d): perf score=2.188937
I20260812 06:16:48.840728  8356 maintenance_manager.cc:643] P 8861b0bf87134f88b5b93aec1aa63d3a: FlushDeltaMemStoresOp(835731265bd54d31b267935835cd167d) complete. Timing: real 0.016s	user 0.011s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6464,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":500}
I20260812 06:16:48.841365  8452 maintenance_manager.cc:419] P 8861b0bf87134f88b5b93aec1aa63d3a: Scheduling MajorDeltaCompactionOp(835731265bd54d31b267935835cd167d): perf score=1.000000
I20260812 06:16:48.903297  7841 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.080s	user 0.001s	sys 0.000s
I20260812 06:16:48.903841  7841 tablet_server.cc:179] TabletServer@127.7.168.65:0 shutting down...
I20260812 06:16:48.991348  8356 maintenance_manager.cc:643] P 8861b0bf87134f88b5b93aec1aa63d3a: MajorDeltaCompactionOp(835731265bd54d31b267935835cd167d) complete. Timing: real 0.150s	user 0.106s	sys 0.044s Metrics: {"cfile_cache_hit":229,"cfile_cache_hit_bytes":9316286,"cfile_cache_miss":404,"cfile_cache_miss_bytes":19601919,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1282,"lbm_read_time_us":8489,"lbm_reads_lt_1ms":436,"lbm_write_time_us":28523,"lbm_writes_lt_1ms":643,"mutex_wait_us":26,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":84096,"update_count":3000}
I20260812 06:16:48.992102  7841 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:16:48.992417  7841 tablet_replica.cc:333] T 835731265bd54d31b267935835cd167d P 8861b0bf87134f88b5b93aec1aa63d3a: stopping tablet replica
I20260812 06:16:48.992583  7841 raft_consensus.cc:2243] T 835731265bd54d31b267935835cd167d P 8861b0bf87134f88b5b93aec1aa63d3a [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:48.992758  7841 raft_consensus.cc:2272] T 835731265bd54d31b267935835cd167d P 8861b0bf87134f88b5b93aec1aa63d3a [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:49.007351  7841 tablet_server.cc:196] TabletServer@127.7.168.65:0 shutdown complete.
I20260812 06:16:49.043581  7841 master.cc:562] Master@127.7.168.126:39905 shutting down...
I20260812 06:16:49.047039  7841 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 1adb1fb039cc46f78492ae9a6d812815 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:49.047196  7841 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 1adb1fb039cc46f78492ae9a6d812815 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:49.047245  7841 tablet_replica.cc:333] T 00000000000000000000000000000000 P 1adb1fb039cc46f78492ae9a6d812815: stopping tablet replica
I20260812 06:16:49.059501  7841 master.cc:584] Master@127.7.168.126:39905 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5271 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10691 ms total)

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