[==========] 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:53.737282 11286 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.11.5.190:33317
I20260812 06:16:53.738329 11286 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:53.738942 11286 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:53.745920 11294 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:53.745930 11291 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:53.746173 11286 server_base.cc:1061] running on GCE node
W20260812 06:16:53.746284 11292 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:53.746820 11286 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:53.746946 11286 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:53.747025 11286 hybrid_clock.cc:648] HybridClock initialized: now 1786515413747022 us; error 0 us; skew 500 ppm
I20260812 06:16:53.749110 11286 webserver.cc:533] Webserver started at http://127.11.5.190:37855/ using document root <none> and password file <none>
I20260812 06:16:53.749751 11286 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:53.749825 11286 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:53.750102 11286 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:53.752195 11286 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413725926-11286-0/minicluster-data/master-0-root/instance:
uuid: "458ae5905b6c40e99143115890475772"
format_stamp: "Formatted at 2026-08-12 06:16:53 on dist-test-slave-f7th"
I20260812 06:16:53.756485 11286 fs_manager.cc:696] Time spent creating directory manager: real 0.004s	user 0.004s	sys 0.000s
I20260812 06:16:53.758862 11299 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:53.760064 11286 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.003s	sys 0.001s
I20260812 06:16:53.760174 11286 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413725926-11286-0/minicluster-data/master-0-root
uuid: "458ae5905b6c40e99143115890475772"
format_stamp: "Formatted at 2026-08-12 06:16:53 on dist-test-slave-f7th"
I20260812 06:16:53.760268 11286 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413725926-11286-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413725926-11286-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413725926-11286-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:53.773751 11286 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:53.774500 11286 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:53.774662 11286 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:53.783389 11351 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.11.5.190:33317 every 8 connection(s)
I20260812 06:16:53.783408 11286 rpc_server.cc:307] RPC server started. Bound to: 127.11.5.190:33317
I20260812 06:16:53.786028 11352 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:53.791429 11352 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 458ae5905b6c40e99143115890475772: Bootstrap starting.
I20260812 06:16:53.794415 11352 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 458ae5905b6c40e99143115890475772: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:53.795344 11352 log.cc:826] T 00000000000000000000000000000000 P 458ae5905b6c40e99143115890475772: Log is configured to *not* fsync() on all Append() calls
I20260812 06:16:53.797099 11352 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 458ae5905b6c40e99143115890475772: No bootstrap required, opened a new log
I20260812 06:16:53.800001 11352 raft_consensus.cc:359] T 00000000000000000000000000000000 P 458ae5905b6c40e99143115890475772 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "458ae5905b6c40e99143115890475772" member_type: VOTER }
I20260812 06:16:53.800165 11352 raft_consensus.cc:385] T 00000000000000000000000000000000 P 458ae5905b6c40e99143115890475772 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:53.800230 11352 raft_consensus.cc:740] T 00000000000000000000000000000000 P 458ae5905b6c40e99143115890475772 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 458ae5905b6c40e99143115890475772, State: Initialized, Role: FOLLOWER
I20260812 06:16:53.800846 11352 consensus_queue.cc:260] T 00000000000000000000000000000000 P 458ae5905b6c40e99143115890475772 [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: "458ae5905b6c40e99143115890475772" member_type: VOTER }
I20260812 06:16:53.800997 11352 raft_consensus.cc:399] T 00000000000000000000000000000000 P 458ae5905b6c40e99143115890475772 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:53.801057 11352 raft_consensus.cc:493] T 00000000000000000000000000000000 P 458ae5905b6c40e99143115890475772 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:53.801195 11352 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 458ae5905b6c40e99143115890475772 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:53.809167 11352 raft_consensus.cc:515] T 00000000000000000000000000000000 P 458ae5905b6c40e99143115890475772 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "458ae5905b6c40e99143115890475772" member_type: VOTER }
I20260812 06:16:53.809724 11352 leader_election.cc:304] T 00000000000000000000000000000000 P 458ae5905b6c40e99143115890475772 [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: 458ae5905b6c40e99143115890475772; no voters: 
I20260812 06:16:53.810071 11352 leader_election.cc:290] T 00000000000000000000000000000000 P 458ae5905b6c40e99143115890475772 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:53.810331 11355 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 458ae5905b6c40e99143115890475772 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:53.810591 11355 raft_consensus.cc:697] T 00000000000000000000000000000000 P 458ae5905b6c40e99143115890475772 [term 1 LEADER]: Becoming Leader. State: Replica: 458ae5905b6c40e99143115890475772, State: Running, Role: LEADER
I20260812 06:16:53.811057 11355 consensus_queue.cc:237] T 00000000000000000000000000000000 P 458ae5905b6c40e99143115890475772 [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: "458ae5905b6c40e99143115890475772" member_type: VOTER }
I20260812 06:16:53.811242 11352 sys_catalog.cc:565] T 00000000000000000000000000000000 P 458ae5905b6c40e99143115890475772 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:53.812837 11356 sys_catalog.cc:455] T 00000000000000000000000000000000 P 458ae5905b6c40e99143115890475772 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "458ae5905b6c40e99143115890475772" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "458ae5905b6c40e99143115890475772" member_type: VOTER } }
I20260812 06:16:53.812992 11356 sys_catalog.cc:458] T 00000000000000000000000000000000 P 458ae5905b6c40e99143115890475772 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:53.813199 11357 sys_catalog.cc:455] T 00000000000000000000000000000000 P 458ae5905b6c40e99143115890475772 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 458ae5905b6c40e99143115890475772. Latest consensus state: current_term: 1 leader_uuid: "458ae5905b6c40e99143115890475772" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "458ae5905b6c40e99143115890475772" member_type: VOTER } }
I20260812 06:16:53.813270 11357 sys_catalog.cc:458] T 00000000000000000000000000000000 P 458ae5905b6c40e99143115890475772 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:53.813592 11365 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:53.813648 11286 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:53.816042 11365 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:53.820847 11365 catalog_manager.cc:1383] Generated new cluster ID: 77a90b1a4f99478a953145df52897f8f
I20260812 06:16:53.820976 11365 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:53.833365 11365 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:53.834195 11365 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:53.839846 11365 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 458ae5905b6c40e99143115890475772: Generated new TSK 0
I20260812 06:16:53.840493 11365 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:53.846171 11286 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:53.849098 11377 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:53.849136 11375 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:53.849437 11374 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:53.849596 11286 server_base.cc:1061] running on GCE node
I20260812 06:16:53.849782 11286 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:53.849820 11286 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:53.849840 11286 hybrid_clock.cc:648] HybridClock initialized: now 1786515413849840 us; error 0 us; skew 500 ppm
I20260812 06:16:53.850979 11286 webserver.cc:533] Webserver started at http://127.11.5.129:39389/ using document root <none> and password file <none>
I20260812 06:16:53.851147 11286 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:53.851199 11286 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:53.851272 11286 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:53.851643 11286 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413725926-11286-0/minicluster-data/ts-0-root/instance:
uuid: "3092d69752ae4e1fad5e678a27bd9d1e"
format_stamp: "Formatted at 2026-08-12 06:16:53 on dist-test-slave-f7th"
I20260812 06:16:53.853117 11286 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:16:53.854178 11382 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:53.854399 11286 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:16:53.854482 11286 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413725926-11286-0/minicluster-data/ts-0-root
uuid: "3092d69752ae4e1fad5e678a27bd9d1e"
format_stamp: "Formatted at 2026-08-12 06:16:53 on dist-test-slave-f7th"
I20260812 06:16:53.854558 11286 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413725926-11286-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413725926-11286-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413725926-11286-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:53.860635 11286 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:53.861002 11286 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:53.861474 11286 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:53.862318 11286 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:53.862370 11286 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:53.862423 11286 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:53.862453 11286 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:53.872664 11286 rpc_server.cc:307] RPC server started. Bound to: 127.11.5.129:34837
I20260812 06:16:53.874055 11445 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.11.5.129:34837 every 8 connection(s)
I20260812 06:16:53.892135 11446 heartbeater.cc:344] Connected to a master server at 127.11.5.190:33317
I20260812 06:16:53.892469 11446 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:53.893033 11446 heartbeater.cc:507] Master 127.11.5.190:33317 requested a full tablet report, sending...
I20260812 06:16:53.894726 11314 ts_manager.cc:194] Registered new tserver with Master: 3092d69752ae4e1fad5e678a27bd9d1e (127.11.5.129:34837)
I20260812 06:16:53.896337 11314 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:38812
I20260812 06:16:53.897292 11286 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.02379505s
I20260812 06:16:53.910609 11314 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:38822:
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:53.931036 11404 tablet_service.cc:1511] Processing CreateTablet for tablet dec4246709a24903a882ac6e1ff1f18f (DEFAULT_TABLE table=heavy-update-compaction-test [id=804b6ae1f8b2446a8d9065595d00b4f8]), partition=
I20260812 06:16:53.932101 11404 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet dec4246709a24903a882ac6e1ff1f18f. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:53.934898 11458 tablet_bootstrap.cc:492] T dec4246709a24903a882ac6e1ff1f18f P 3092d69752ae4e1fad5e678a27bd9d1e: Bootstrap starting.
I20260812 06:16:53.935986 11458 tablet_bootstrap.cc:654] T dec4246709a24903a882ac6e1ff1f18f P 3092d69752ae4e1fad5e678a27bd9d1e: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:53.937171 11458 tablet_bootstrap.cc:492] T dec4246709a24903a882ac6e1ff1f18f P 3092d69752ae4e1fad5e678a27bd9d1e: No bootstrap required, opened a new log
I20260812 06:16:53.937264 11458 ts_tablet_manager.cc:1403] T dec4246709a24903a882ac6e1ff1f18f P 3092d69752ae4e1fad5e678a27bd9d1e: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:16:53.937736 11458 raft_consensus.cc:359] T dec4246709a24903a882ac6e1ff1f18f P 3092d69752ae4e1fad5e678a27bd9d1e [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3092d69752ae4e1fad5e678a27bd9d1e" member_type: VOTER last_known_addr { host: "127.11.5.129" port: 34837 } }
I20260812 06:16:53.937840 11458 raft_consensus.cc:385] T dec4246709a24903a882ac6e1ff1f18f P 3092d69752ae4e1fad5e678a27bd9d1e [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:53.937870 11458 raft_consensus.cc:740] T dec4246709a24903a882ac6e1ff1f18f P 3092d69752ae4e1fad5e678a27bd9d1e [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 3092d69752ae4e1fad5e678a27bd9d1e, State: Initialized, Role: FOLLOWER
I20260812 06:16:53.938011 11458 consensus_queue.cc:260] T dec4246709a24903a882ac6e1ff1f18f P 3092d69752ae4e1fad5e678a27bd9d1e [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: "3092d69752ae4e1fad5e678a27bd9d1e" member_type: VOTER last_known_addr { host: "127.11.5.129" port: 34837 } }
I20260812 06:16:53.938097 11458 raft_consensus.cc:399] T dec4246709a24903a882ac6e1ff1f18f P 3092d69752ae4e1fad5e678a27bd9d1e [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:53.938131 11458 raft_consensus.cc:493] T dec4246709a24903a882ac6e1ff1f18f P 3092d69752ae4e1fad5e678a27bd9d1e [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:53.938171 11458 raft_consensus.cc:3060] T dec4246709a24903a882ac6e1ff1f18f P 3092d69752ae4e1fad5e678a27bd9d1e [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:53.939056 11458 raft_consensus.cc:515] T dec4246709a24903a882ac6e1ff1f18f P 3092d69752ae4e1fad5e678a27bd9d1e [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3092d69752ae4e1fad5e678a27bd9d1e" member_type: VOTER last_known_addr { host: "127.11.5.129" port: 34837 } }
I20260812 06:16:53.939185 11458 leader_election.cc:304] T dec4246709a24903a882ac6e1ff1f18f P 3092d69752ae4e1fad5e678a27bd9d1e [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: 3092d69752ae4e1fad5e678a27bd9d1e; no voters: 
I20260812 06:16:53.939357 11458 leader_election.cc:290] T dec4246709a24903a882ac6e1ff1f18f P 3092d69752ae4e1fad5e678a27bd9d1e [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:53.939816 11458 ts_tablet_manager.cc:1434] T dec4246709a24903a882ac6e1ff1f18f P 3092d69752ae4e1fad5e678a27bd9d1e: Time spent starting tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:16:53.940274 11446 heartbeater.cc:499] Master 127.11.5.190:33317 was elected leader, sending a full tablet report...
I20260812 06:16:53.943509 11461 raft_consensus.cc:2804] T dec4246709a24903a882ac6e1ff1f18f P 3092d69752ae4e1fad5e678a27bd9d1e [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:53.943778 11461 raft_consensus.cc:697] T dec4246709a24903a882ac6e1ff1f18f P 3092d69752ae4e1fad5e678a27bd9d1e [term 1 LEADER]: Becoming Leader. State: Replica: 3092d69752ae4e1fad5e678a27bd9d1e, State: Running, Role: LEADER
I20260812 06:16:53.943975 11461 consensus_queue.cc:237] T dec4246709a24903a882ac6e1ff1f18f P 3092d69752ae4e1fad5e678a27bd9d1e [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: "3092d69752ae4e1fad5e678a27bd9d1e" member_type: VOTER last_known_addr { host: "127.11.5.129" port: 34837 } }
I20260812 06:16:53.946039 11314 catalog_manager.cc:5719] T dec4246709a24903a882ac6e1ff1f18f P 3092d69752ae4e1fad5e678a27bd9d1e reported cstate change: term changed from 0 to 1, leader changed from <none> to 3092d69752ae4e1fad5e678a27bd9d1e (127.11.5.129). New cstate: current_term: 1 leader_uuid: "3092d69752ae4e1fad5e678a27bd9d1e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3092d69752ae4e1fad5e678a27bd9d1e" member_type: VOTER last_known_addr { host: "127.11.5.129" port: 34837 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:54.044659 11286 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.090s	user 0.017s	sys 0.013s
I20260812 06:16:54.129271 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling FlushMRSOp(dec4246709a24903a882ac6e1ff1f18f): perf score=10.125253
I20260812 06:16:54.341413 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: FlushMRSOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.212s	user 0.129s	sys 0.008s Metrics: {"bytes_written":12307490,"cfile_init":1,"compiler_manager_pool.queue_time_us":1279,"delete_count":0,"dirs.queue_time_us":46,"dirs.run_cpu_time_us":164,"dirs.run_wall_time_us":687,"drs_written":1,"lbm_read_time_us":71,"lbm_reads_lt_1ms":4,"lbm_write_time_us":37202,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":556,"peak_mem_usage":0,"reinsert_count":0,"rows_written":102,"spinlock_wait_cycles":1280,"update_count":1500}
I20260812 06:16:54.342520 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f): perf score=2.188937
I20260812 06:16:54.355677 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.013s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4887,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:54.356189 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling LogGCOp(dec4246709a24903a882ac6e1ff1f18f): free 8725963 bytes of WAL
I20260812 06:16:54.356508 11387 log_reader.cc:385] T dec4246709a24903a882ac6e1ff1f18f: removed 1 log segments from log reader
I20260812 06:16:54.356612 11387 log.cc:1079] T dec4246709a24903a882ac6e1ff1f18f P 3092d69752ae4e1fad5e678a27bd9d1e: Deleting log segment in path: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413725926-11286-0/minicluster-data/ts-0-root/wals/dec4246709a24903a882ac6e1ff1f18f/wal-000000001 (ops 1-6)
I20260812 06:16:54.358814 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: LogGCOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:16:54.359297 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling MajorDeltaCompactionOp(dec4246709a24903a882ac6e1ff1f18f): perf score=1.000000
I20260812 06:16:54.497821 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: MajorDeltaCompactionOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.138s	user 0.102s	sys 0.031s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590347,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1685,"lbm_read_time_us":10458,"lbm_reads_1-10_ms":1,"lbm_reads_lt_1ms":467,"lbm_write_time_us":23666,"lbm_writes_lt_1ms":443,"mutex_wait_us":490,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":324,"threads_started":5,"update_count":2000}
I20260812 06:16:54.498409 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f): perf score=10.126437
I20260812 06:16:54.539124 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.040s	user 0.020s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15053,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:54.539566 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling UndoDeltaBlockGCOp(dec4246709a24903a882ac6e1ff1f18f): 8206537 bytes on disk
I20260812 06:16:54.540023 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: UndoDeltaBlockGCOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4}
I20260812 06:16:54.540452 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f): perf score=2.188937
I20260812 06:16:54.553635 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.013s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4248,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:54.554097 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling MajorDeltaCompactionOp(dec4246709a24903a882ac6e1ff1f18f): perf score=1.000000
I20260812 06:16:54.667781 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: MajorDeltaCompactionOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.114s	user 0.096s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590347,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":2015,"lbm_read_time_us":7729,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21634,"lbm_writes_lt_1ms":443,"mutex_wait_us":1802,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:16:54.668284 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f): perf score=10.126437
I20260812 06:16:54.719555 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.051s	user 0.026s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14289,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:54.720072 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f): perf score=2.188937
I20260812 06:16:54.729763 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3587,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:54.730154 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling MajorDeltaCompactionOp(dec4246709a24903a882ac6e1ff1f18f): perf score=1.000000
I20260812 06:16:54.893404 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: MajorDeltaCompactionOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.163s	user 0.106s	sys 0.057s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590347,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":541,"lbm_read_time_us":9450,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27035,"lbm_writes_lt_1ms":443,"mutex_wait_us":205,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:16:54.893858 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f): perf score=10.126437
I20260812 06:16:54.931933 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.038s	user 0.022s	sys 0.015s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":18404,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:16:54.932464 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f): perf score=2.188937
I20260812 06:16:54.947461 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5116,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:54.948062 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling MajorDeltaCompactionOp(dec4246709a24903a882ac6e1ff1f18f): perf score=1.000000
I20260812 06:16:55.067780 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: MajorDeltaCompactionOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.119s	user 0.087s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590349,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":268,"lbm_read_time_us":6797,"lbm_reads_lt_1ms":464,"lbm_write_time_us":21613,"lbm_writes_lt_1ms":443,"mutex_wait_us":30,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":64000,"update_count":2000}
I20260812 06:16:55.068312 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f): perf score=10.126437
I20260812 06:16:55.114692 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.046s	user 0.019s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14707,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:55.115388 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f): perf score=2.188937
I20260812 06:16:55.130751 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5842,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:55.131361 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling MajorDeltaCompactionOp(dec4246709a24903a882ac6e1ff1f18f): perf score=1.000000
I20260812 06:16:55.257969 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: MajorDeltaCompactionOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.126s	user 0.075s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590347,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":435,"lbm_read_time_us":9302,"lbm_reads_lt_1ms":464,"lbm_write_time_us":20879,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:16:55.258473 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f): perf score=10.126437
I20260812 06:16:55.308704 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.050s	user 0.030s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14816,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:55.309165 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f): perf score=2.188937
I20260812 06:16:55.324203 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.015s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5375,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:55.324666 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling MajorDeltaCompactionOp(dec4246709a24903a882ac6e1ff1f18f): perf score=1.000000
I20260812 06:16:55.453975 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: MajorDeltaCompactionOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.129s	user 0.108s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590347,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":226,"lbm_read_time_us":10211,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22612,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:16:55.454501 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f): perf score=10.126437
I20260812 06:16:55.500893 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.046s	user 0.024s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14124,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:55.501499 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f): perf score=2.188937
I20260812 06:16:55.515260 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.014s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5102,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:55.515865 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling FlushMRSOp(dec4246709a24903a882ac6e1ff1f18f): perf score=1.000000
I20260812 06:16:55.558748 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: FlushMRSOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.043s	user 0.026s	sys 0.001s Metrics: {"bytes_written":1152509,"cfile_init":1,"dirs.queue_time_us":115,"dirs.run_cpu_time_us":195,"dirs.run_wall_time_us":1112,"drs_written":1,"lbm_read_time_us":43,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1347,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:16:55.559774 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling LogGCOp(dec4246709a24903a882ac6e1ff1f18f): free 112239308 bytes of WAL
I20260812 06:16:55.560081 11387 log_reader.cc:385] T dec4246709a24903a882ac6e1ff1f18f: removed 11 log segments from log reader
I20260812 06:16:55.560184 11387 log.cc:1079] T dec4246709a24903a882ac6e1ff1f18f P 3092d69752ae4e1fad5e678a27bd9d1e: Deleting log segment in path: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413725926-11286-0/minicluster-data/ts-0-root/wals/dec4246709a24903a882ac6e1ff1f18f/wal-000000002 (ops 7-10)
I20260812 06:16:55.560278 11387 log.cc:1079] T dec4246709a24903a882ac6e1ff1f18f P 3092d69752ae4e1fad5e678a27bd9d1e: Deleting log segment in path: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413725926-11286-0/minicluster-data/ts-0-root/wals/dec4246709a24903a882ac6e1ff1f18f/wal-000000003 (ops 11-15)
I20260812 06:16:55.560366 11387 log.cc:1079] T dec4246709a24903a882ac6e1ff1f18f P 3092d69752ae4e1fad5e678a27bd9d1e: Deleting log segment in path: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413725926-11286-0/minicluster-data/ts-0-root/wals/dec4246709a24903a882ac6e1ff1f18f/wal-000000004 (ops 16-20)
I20260812 06:16:55.560438 11387 log.cc:1079] T dec4246709a24903a882ac6e1ff1f18f P 3092d69752ae4e1fad5e678a27bd9d1e: Deleting log segment in path: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413725926-11286-0/minicluster-data/ts-0-root/wals/dec4246709a24903a882ac6e1ff1f18f/wal-000000005 (ops 21-25)
I20260812 06:16:55.560519 11387 log.cc:1079] T dec4246709a24903a882ac6e1ff1f18f P 3092d69752ae4e1fad5e678a27bd9d1e: Deleting log segment in path: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413725926-11286-0/minicluster-data/ts-0-root/wals/dec4246709a24903a882ac6e1ff1f18f/wal-000000006 (ops 26-30)
I20260812 06:16:55.560608 11387 log.cc:1079] T dec4246709a24903a882ac6e1ff1f18f P 3092d69752ae4e1fad5e678a27bd9d1e: Deleting log segment in path: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413725926-11286-0/minicluster-data/ts-0-root/wals/dec4246709a24903a882ac6e1ff1f18f/wal-000000007 (ops 31-35)
I20260812 06:16:55.560679 11387 log.cc:1079] T dec4246709a24903a882ac6e1ff1f18f P 3092d69752ae4e1fad5e678a27bd9d1e: Deleting log segment in path: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413725926-11286-0/minicluster-data/ts-0-root/wals/dec4246709a24903a882ac6e1ff1f18f/wal-000000008 (ops 36-40)
I20260812 06:16:55.560758 11387 log.cc:1079] T dec4246709a24903a882ac6e1ff1f18f P 3092d69752ae4e1fad5e678a27bd9d1e: Deleting log segment in path: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413725926-11286-0/minicluster-data/ts-0-root/wals/dec4246709a24903a882ac6e1ff1f18f/wal-000000009 (ops 41-45)
I20260812 06:16:55.560798 11387 log.cc:1079] T dec4246709a24903a882ac6e1ff1f18f P 3092d69752ae4e1fad5e678a27bd9d1e: Deleting log segment in path: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413725926-11286-0/minicluster-data/ts-0-root/wals/dec4246709a24903a882ac6e1ff1f18f/wal-000000010 (ops 46-50)
I20260812 06:16:55.560827 11387 log.cc:1079] T dec4246709a24903a882ac6e1ff1f18f P 3092d69752ae4e1fad5e678a27bd9d1e: Deleting log segment in path: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413725926-11286-0/minicluster-data/ts-0-root/wals/dec4246709a24903a882ac6e1ff1f18f/wal-000000011 (ops 51-55)
I20260812 06:16:55.560856 11387 log.cc:1079] T dec4246709a24903a882ac6e1ff1f18f P 3092d69752ae4e1fad5e678a27bd9d1e: Deleting log segment in path: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413725926-11286-0/minicluster-data/ts-0-root/wals/dec4246709a24903a882ac6e1ff1f18f/wal-000000012 (ops 56-60)
I20260812 06:16:55.586076 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: LogGCOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.026s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:16:55.586552 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling UndoDeltaBlockGCOp(dec4246709a24903a882ac6e1ff1f18f): 447 bytes on disk
I20260812 06:16:55.587090 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: UndoDeltaBlockGCOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":69,"lbm_reads_lt_1ms":4}
I20260812 06:16:55.587889 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f): perf score=3.181125
I20260812 06:16:55.613634 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.025s	user 0.014s	sys 0.001s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":6931,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:55.614214 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f): perf score=2.188937
I20260812 06:16:55.627534 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4838,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:55.627992 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling MajorDeltaCompactionOp(dec4246709a24903a882ac6e1ff1f18f): perf score=1.000000
I20260812 06:16:55.840747 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: MajorDeltaCompactionOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.213s	user 0.134s	sys 0.074s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28795399,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":706,"lbm_read_time_us":13677,"lbm_reads_lt_1ms":674,"lbm_write_time_us":35353,"lbm_writes_lt_1ms":643,"mutex_wait_us":69,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":6784,"thread_start_us":68,"threads_started":1,"update_count":3000}
I20260812 06:16:55.841346 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f): perf score=14.095187
I20260812 06:16:55.884078 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.043s	user 0.026s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18567,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:55.884611 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling MajorDeltaCompactionOp(dec4246709a24903a882ac6e1ff1f18f): perf score=1.000000
I20260812 06:16:56.031736 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: MajorDeltaCompactionOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.147s	user 0.105s	sys 0.038s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20590228,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1283,"lbm_read_time_us":9545,"lbm_reads_lt_1ms":467,"lbm_write_time_us":25276,"lbm_writes_lt_1ms":443,"mutex_wait_us":1020,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3712,"update_count":2000}
I20260812 06:16:56.032226 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f): perf score=10.126437
I20260812 06:16:56.071142 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.039s	user 0.024s	sys 0.012s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":16526,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:56.071631 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f): perf score=2.188937
I20260812 06:16:56.081820 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3924,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:56.082285 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling MajorDeltaCompactionOp(dec4246709a24903a882ac6e1ff1f18f): perf score=1.000000
I20260812 06:16:56.222772 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: MajorDeltaCompactionOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.140s	user 0.094s	sys 0.037s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590349,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":666,"lbm_read_time_us":8282,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23425,"lbm_writes_lt_1ms":443,"mutex_wait_us":48,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":384,"update_count":2000}
I20260812 06:16:56.223284 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f): perf score=10.126437
I20260812 06:16:56.262336 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.039s	user 0.027s	sys 0.008s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15889,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:56.262800 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling MajorDeltaCompactionOp(dec4246709a24903a882ac6e1ff1f18f): perf score=1.000000
I20260812 06:16:56.390620 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: MajorDeltaCompactionOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.128s	user 0.098s	sys 0.023s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16487817,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1099,"lbm_read_time_us":6318,"lbm_reads_lt_1ms":363,"lbm_write_time_us":20233,"lbm_writes_lt_1ms":343,"mutex_wait_us":311,"peak_mem_usage":38262756,"reinsert_count":0,"update_count":1500}
I20260812 06:16:56.391129 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f): perf score=10.126437
I20260812 06:16:56.426144 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.035s	user 0.016s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15557,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:56.426575 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling MajorDeltaCompactionOp(dec4246709a24903a882ac6e1ff1f18f): perf score=1.000000
I20260812 06:16:56.561084 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: MajorDeltaCompactionOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.134s	user 0.085s	sys 0.033s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16487816,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1227,"lbm_read_time_us":8776,"lbm_reads_lt_1ms":367,"lbm_write_time_us":17170,"lbm_writes_lt_1ms":343,"mutex_wait_us":857,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":1536,"update_count":1500}
I20260812 06:16:56.561679 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f): perf score=10.126437
I20260812 06:16:56.608383 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.046s	user 0.019s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16083,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:56.608877 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f): perf score=2.188937
I20260812 06:16:56.622624 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.014s	user 0.000s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5243,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:56.623190 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling MajorDeltaCompactionOp(dec4246709a24903a882ac6e1ff1f18f): perf score=1.000000
I20260812 06:16:56.780316 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: MajorDeltaCompactionOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.157s	user 0.105s	sys 0.043s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590347,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":84,"lbm_read_time_us":9416,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28155,"lbm_writes_lt_1ms":443,"mutex_wait_us":49,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:16:56.780947 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f): perf score=10.126437
I20260812 06:16:56.829666 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.048s	user 0.024s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16487,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":71936,"update_count":1500}
I20260812 06:16:56.830173 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling MajorDeltaCompactionOp(dec4246709a24903a882ac6e1ff1f18f): perf score=1.000000
I20260812 06:16:56.948493 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: MajorDeltaCompactionOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.118s	user 0.096s	sys 0.021s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16487816,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":818,"lbm_read_time_us":7034,"lbm_reads_lt_1ms":363,"lbm_write_time_us":21560,"lbm_writes_lt_1ms":343,"mutex_wait_us":419,"peak_mem_usage":38262756,"reinsert_count":0,"update_count":1500}
I20260812 06:16:56.949012 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f): perf score=10.126437
I20260812 06:16:56.988102 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.039s	user 0.034s	sys 0.000s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15592,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:16:56.988641 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f): perf score=2.188937
I20260812 06:16:57.002883 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.014s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5202,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:57.003415 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling MajorDeltaCompactionOp(dec4246709a24903a882ac6e1ff1f18f): perf score=1.000000
I20260812 06:16:57.153569 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: MajorDeltaCompactionOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.150s	user 0.101s	sys 0.041s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590347,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1699,"lbm_read_time_us":7527,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27608,"lbm_writes_lt_1ms":443,"mutex_wait_us":624,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12416,"update_count":2000}
I20260812 06:16:57.154218 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f): perf score=10.126437
I20260812 06:16:57.200548 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.046s	user 0.020s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14434,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:57.201105 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f): perf score=2.188937
I20260812 06:16:57.214221 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.013s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4860,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:57.214975 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling FlushMRSOp(dec4246709a24903a882ac6e1ff1f18f): perf score=1.000000
I20260812 06:16:57.242938 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: FlushMRSOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.028s	user 0.025s	sys 0.000s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":86,"dirs.run_cpu_time_us":169,"dirs.run_wall_time_us":1780,"drs_written":1,"lbm_read_time_us":78,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1314,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:16:57.243731 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling LogGCOp(dec4246709a24903a882ac6e1ff1f18f): free 132571309 bytes of WAL
I20260812 06:16:57.243960 11387 log_reader.cc:385] T dec4246709a24903a882ac6e1ff1f18f: removed 13 log segments from log reader
I20260812 06:16:57.244017 11387 log.cc:1079] T dec4246709a24903a882ac6e1ff1f18f P 3092d69752ae4e1fad5e678a27bd9d1e: Deleting log segment in path: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413725926-11286-0/minicluster-data/ts-0-root/wals/dec4246709a24903a882ac6e1ff1f18f/wal-000000013 (ops 61-65)
I20260812 06:16:57.244108 11387 log.cc:1079] T dec4246709a24903a882ac6e1ff1f18f P 3092d69752ae4e1fad5e678a27bd9d1e: Deleting log segment in path: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413725926-11286-0/minicluster-data/ts-0-root/wals/dec4246709a24903a882ac6e1ff1f18f/wal-000000014 (ops 66-70)
I20260812 06:16:57.244148 11387 log.cc:1079] T dec4246709a24903a882ac6e1ff1f18f P 3092d69752ae4e1fad5e678a27bd9d1e: Deleting log segment in path: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413725926-11286-0/minicluster-data/ts-0-root/wals/dec4246709a24903a882ac6e1ff1f18f/wal-000000015 (ops 71-75)
I20260812 06:16:57.244215 11387 log.cc:1079] T dec4246709a24903a882ac6e1ff1f18f P 3092d69752ae4e1fad5e678a27bd9d1e: Deleting log segment in path: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413725926-11286-0/minicluster-data/ts-0-root/wals/dec4246709a24903a882ac6e1ff1f18f/wal-000000016 (ops 76-80)
I20260812 06:16:57.244246 11387 log.cc:1079] T dec4246709a24903a882ac6e1ff1f18f P 3092d69752ae4e1fad5e678a27bd9d1e: Deleting log segment in path: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413725926-11286-0/minicluster-data/ts-0-root/wals/dec4246709a24903a882ac6e1ff1f18f/wal-000000017 (ops 81-84)
I20260812 06:16:57.244287 11387 log.cc:1079] T dec4246709a24903a882ac6e1ff1f18f P 3092d69752ae4e1fad5e678a27bd9d1e: Deleting log segment in path: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413725926-11286-0/minicluster-data/ts-0-root/wals/dec4246709a24903a882ac6e1ff1f18f/wal-000000018 (ops 85-89)
I20260812 06:16:57.244333 11387 log.cc:1079] T dec4246709a24903a882ac6e1ff1f18f P 3092d69752ae4e1fad5e678a27bd9d1e: Deleting log segment in path: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413725926-11286-0/minicluster-data/ts-0-root/wals/dec4246709a24903a882ac6e1ff1f18f/wal-000000019 (ops 90-94)
I20260812 06:16:57.244371 11387 log.cc:1079] T dec4246709a24903a882ac6e1ff1f18f P 3092d69752ae4e1fad5e678a27bd9d1e: Deleting log segment in path: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413725926-11286-0/minicluster-data/ts-0-root/wals/dec4246709a24903a882ac6e1ff1f18f/wal-000000020 (ops 95-99)
I20260812 06:16:57.244407 11387 log.cc:1079] T dec4246709a24903a882ac6e1ff1f18f P 3092d69752ae4e1fad5e678a27bd9d1e: Deleting log segment in path: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413725926-11286-0/minicluster-data/ts-0-root/wals/dec4246709a24903a882ac6e1ff1f18f/wal-000000021 (ops 100-104)
I20260812 06:16:57.244438 11387 log.cc:1079] T dec4246709a24903a882ac6e1ff1f18f P 3092d69752ae4e1fad5e678a27bd9d1e: Deleting log segment in path: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413725926-11286-0/minicluster-data/ts-0-root/wals/dec4246709a24903a882ac6e1ff1f18f/wal-000000022 (ops 105-108)
I20260812 06:16:57.244493 11387 log.cc:1079] T dec4246709a24903a882ac6e1ff1f18f P 3092d69752ae4e1fad5e678a27bd9d1e: Deleting log segment in path: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413725926-11286-0/minicluster-data/ts-0-root/wals/dec4246709a24903a882ac6e1ff1f18f/wal-000000023 (ops 109-113)
I20260812 06:16:57.244527 11387 log.cc:1079] T dec4246709a24903a882ac6e1ff1f18f P 3092d69752ae4e1fad5e678a27bd9d1e: Deleting log segment in path: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413725926-11286-0/minicluster-data/ts-0-root/wals/dec4246709a24903a882ac6e1ff1f18f/wal-000000024 (ops 114-118)
I20260812 06:16:57.244578 11387 log.cc:1079] T dec4246709a24903a882ac6e1ff1f18f P 3092d69752ae4e1fad5e678a27bd9d1e: Deleting log segment in path: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413725926-11286-0/minicluster-data/ts-0-root/wals/dec4246709a24903a882ac6e1ff1f18f/wal-000000025 (ops 119-123)
I20260812 06:16:57.275161 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: LogGCOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.031s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:16:57.275646 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling UndoDeltaBlockGCOp(dec4246709a24903a882ac6e1ff1f18f): 483 bytes on disk
I20260812 06:16:57.276113 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: UndoDeltaBlockGCOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4}
I20260812 06:16:57.276736 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f): perf score=3.181125
I20260812 06:16:57.296742 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.020s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":7008,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:57.297212 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f): perf score=2.188937
I20260812 06:16:57.309203 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4037,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:57.309804 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling MajorDeltaCompactionOp(dec4246709a24903a882ac6e1ff1f18f): perf score=1.000000
I20260812 06:16:57.488297 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: MajorDeltaCompactionOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.178s	user 0.133s	sys 0.037s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28795399,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":66,"lbm_read_time_us":12109,"lbm_reads_lt_1ms":674,"lbm_write_time_us":36656,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":642,"mutex_wait_us":29,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":9088,"thread_start_us":85,"threads_started":1,"update_count":3000}
I20260812 06:16:57.490854 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f): perf score=14.095187
I20260812 06:16:57.536159 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.045s	user 0.021s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19830,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:57.536681 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f): perf score=2.188937
I20260812 06:16:57.550411 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.014s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5201,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:57.550961 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling MajorDeltaCompactionOp(dec4246709a24903a882ac6e1ff1f18f): perf score=1.000000
I20260812 06:16:57.703751 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: MajorDeltaCompactionOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.153s	user 0.123s	sys 0.028s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24692758,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":923,"lbm_read_time_us":10937,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30059,"lbm_writes_lt_1ms":543,"mutex_wait_us":282,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2500}
I20260812 06:16:57.704300 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f): perf score=10.126437
I20260812 06:16:57.745020 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.041s	user 0.023s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17059,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:57.745620 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f): perf score=2.188937
I20260812 06:16:57.762221 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.016s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6789,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:57.762658 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling MajorDeltaCompactionOp(dec4246709a24903a882ac6e1ff1f18f): perf score=1.000000
I20260812 06:16:57.895684 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: MajorDeltaCompactionOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.133s	user 0.116s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590347,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":238,"lbm_read_time_us":9631,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25149,"lbm_writes_lt_1ms":443,"mutex_wait_us":103,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":2000}
I20260812 06:16:57.896158 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f): perf score=10.126437
I20260812 06:16:57.943216 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.047s	user 0.020s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15019,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:57.943758 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f): perf score=2.188937
I20260812 06:16:57.959906 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.016s	user 0.013s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5636,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:57.960457 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling MajorDeltaCompactionOp(dec4246709a24903a882ac6e1ff1f18f): perf score=1.000000
I20260812 06:16:58.079886 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: MajorDeltaCompactionOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.119s	user 0.104s	sys 0.011s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590347,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1046,"lbm_read_time_us":8273,"lbm_reads_lt_1ms":464,"lbm_write_time_us":21297,"lbm_writes_lt_1ms":443,"mutex_wait_us":311,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":2000}
I20260812 06:16:58.080480 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f): perf score=10.126437
I20260812 06:16:58.135223 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.054s	user 0.025s	sys 0.019s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":17373,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:58.136039 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f): perf score=2.188937
I20260812 06:16:58.151770 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.016s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5795,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:58.152276 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling MajorDeltaCompactionOp(dec4246709a24903a882ac6e1ff1f18f): perf score=1.000000
I20260812 06:16:58.292484 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: MajorDeltaCompactionOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.140s	user 0.100s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590349,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":254,"lbm_read_time_us":10399,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22096,"lbm_writes_lt_1ms":443,"mutex_wait_us":25,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13056,"update_count":2000}
I20260812 06:16:58.293037 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f): perf score=7.149875
I20260812 06:16:58.317381 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.024s	user 0.014s	sys 0.008s Metrics: {"bytes_written":8615324,"delete_count":0,"lbm_write_time_us":10197,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:16:58.317946 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f): perf score=2.188937
I20260812 06:16:58.332707 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.015s	user 0.007s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4372,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:58.333274 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling MajorDeltaCompactionOp(dec4246709a24903a882ac6e1ff1f18f): perf score=1.000000
I20260812 06:16:58.431294 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: MajorDeltaCompactionOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.098s	user 0.090s	sys 0.008s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16487927,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":512,"lbm_read_time_us":7696,"lbm_reads_lt_1ms":368,"lbm_write_time_us":16183,"lbm_writes_lt_1ms":343,"mutex_wait_us":297,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":6784,"update_count":1500}
I20260812 06:16:58.431922 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f): perf score=6.157687
I20260812 06:16:58.475128 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.043s	user 0.015s	sys 0.012s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":12706,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":202,"reinsert_count":0,"update_count":1000}
I20260812 06:16:58.475826 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f): perf score=2.188937
I20260812 06:16:58.489296 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.013s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5005,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:58.489799 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling MajorDeltaCompactionOp(dec4246709a24903a882ac6e1ff1f18f): perf score=1.000000
I20260812 06:16:58.619235 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: MajorDeltaCompactionOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.129s	user 0.082s	sys 0.036s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16487935,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1092,"lbm_read_time_us":7459,"lbm_reads_lt_1ms":372,"lbm_write_time_us":21887,"lbm_writes_lt_1ms":343,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":1500}
I20260812 06:16:58.619815 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f): perf score=10.126437
I20260812 06:16:58.655174 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.035s	user 0.022s	sys 0.008s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":14561,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:58.655783 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling FlushMRSOp(dec4246709a24903a882ac6e1ff1f18f): perf score=1.000000
I20260812 06:16:58.691318 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: FlushMRSOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.035s	user 0.024s	sys 0.000s Metrics: {"bytes_written":1193505,"cfile_init":1,"dirs.queue_time_us":190,"dirs.run_cpu_time_us":300,"dirs.run_wall_time_us":1572,"drs_written":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1312,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:16:58.692291 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling LogGCOp(dec4246709a24903a882ac6e1ff1f18f): free 112692591 bytes of WAL
I20260812 06:16:58.692556 11387 log_reader.cc:385] T dec4246709a24903a882ac6e1ff1f18f: removed 11 log segments from log reader
I20260812 06:16:58.692613 11387 log.cc:1079] T dec4246709a24903a882ac6e1ff1f18f P 3092d69752ae4e1fad5e678a27bd9d1e: Deleting log segment in path: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413725926-11286-0/minicluster-data/ts-0-root/wals/dec4246709a24903a882ac6e1ff1f18f/wal-000000026 (ops 124-128)
I20260812 06:16:58.692652 11387 log.cc:1079] T dec4246709a24903a882ac6e1ff1f18f P 3092d69752ae4e1fad5e678a27bd9d1e: Deleting log segment in path: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413725926-11286-0/minicluster-data/ts-0-root/wals/dec4246709a24903a882ac6e1ff1f18f/wal-000000027 (ops 129-133)
I20260812 06:16:58.692732 11387 log.cc:1079] T dec4246709a24903a882ac6e1ff1f18f P 3092d69752ae4e1fad5e678a27bd9d1e: Deleting log segment in path: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413725926-11286-0/minicluster-data/ts-0-root/wals/dec4246709a24903a882ac6e1ff1f18f/wal-000000028 (ops 134-138)
I20260812 06:16:58.692773 11387 log.cc:1079] T dec4246709a24903a882ac6e1ff1f18f P 3092d69752ae4e1fad5e678a27bd9d1e: Deleting log segment in path: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413725926-11286-0/minicluster-data/ts-0-root/wals/dec4246709a24903a882ac6e1ff1f18f/wal-000000029 (ops 139-143)
I20260812 06:16:58.692799 11387 log.cc:1079] T dec4246709a24903a882ac6e1ff1f18f P 3092d69752ae4e1fad5e678a27bd9d1e: Deleting log segment in path: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413725926-11286-0/minicluster-data/ts-0-root/wals/dec4246709a24903a882ac6e1ff1f18f/wal-000000030 (ops 144-148)
I20260812 06:16:58.692864 11387 log.cc:1079] T dec4246709a24903a882ac6e1ff1f18f P 3092d69752ae4e1fad5e678a27bd9d1e: Deleting log segment in path: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413725926-11286-0/minicluster-data/ts-0-root/wals/dec4246709a24903a882ac6e1ff1f18f/wal-000000031 (ops 149-153)
I20260812 06:16:58.692903 11387 log.cc:1079] T dec4246709a24903a882ac6e1ff1f18f P 3092d69752ae4e1fad5e678a27bd9d1e: Deleting log segment in path: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413725926-11286-0/minicluster-data/ts-0-root/wals/dec4246709a24903a882ac6e1ff1f18f/wal-000000032 (ops 154-158)
I20260812 06:16:58.692976 11387 log.cc:1079] T dec4246709a24903a882ac6e1ff1f18f P 3092d69752ae4e1fad5e678a27bd9d1e: Deleting log segment in path: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413725926-11286-0/minicluster-data/ts-0-root/wals/dec4246709a24903a882ac6e1ff1f18f/wal-000000033 (ops 159-163)
I20260812 06:16:58.693012 11387 log.cc:1079] T dec4246709a24903a882ac6e1ff1f18f P 3092d69752ae4e1fad5e678a27bd9d1e: Deleting log segment in path: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413725926-11286-0/minicluster-data/ts-0-root/wals/dec4246709a24903a882ac6e1ff1f18f/wal-000000034 (ops 164-168)
I20260812 06:16:58.693068 11387 log.cc:1079] T dec4246709a24903a882ac6e1ff1f18f P 3092d69752ae4e1fad5e678a27bd9d1e: Deleting log segment in path: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413725926-11286-0/minicluster-data/ts-0-root/wals/dec4246709a24903a882ac6e1ff1f18f/wal-000000035 (ops 169-173)
I20260812 06:16:58.693109 11387 log.cc:1079] T dec4246709a24903a882ac6e1ff1f18f P 3092d69752ae4e1fad5e678a27bd9d1e: Deleting log segment in path: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413725926-11286-0/minicluster-data/ts-0-root/wals/dec4246709a24903a882ac6e1ff1f18f/wal-000000036 (ops 174-178)
I20260812 06:16:58.716833 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: LogGCOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.024s	user 0.001s	sys 0.021s Metrics: {}
I20260812 06:16:58.717378 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling UndoDeltaBlockGCOp(dec4246709a24903a882ac6e1ff1f18f): 462 bytes on disk
I20260812 06:16:58.717909 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: UndoDeltaBlockGCOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4}
I20260812 06:16:58.718689 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f): perf score=6.157687
I20260812 06:16:58.748495 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.030s	user 0.021s	sys 0.004s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":9577,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:58.749217 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling LogGCOp(dec4246709a24903a882ac6e1ff1f18f): free 12017949 bytes of WAL
I20260812 06:16:58.749513 11387 log_reader.cc:385] T dec4246709a24903a882ac6e1ff1f18f: removed 1 log segments from log reader
I20260812 06:16:58.749567 11387 log.cc:1079] T dec4246709a24903a882ac6e1ff1f18f P 3092d69752ae4e1fad5e678a27bd9d1e: Deleting log segment in path: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413725926-11286-0/minicluster-data/ts-0-root/wals/dec4246709a24903a882ac6e1ff1f18f/wal-000000037 (ops 179-183)
I20260812 06:16:58.751403 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: LogGCOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:16:58.751888 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f): perf score=1.000000
I20260812 06:16:58.761080 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.009s	user 0.007s	sys 0.000s Metrics: {"bytes_written":2092431,"delete_count":0,"lbm_write_time_us":2428,"lbm_writes_lt_1ms":54,"reinsert_count":0,"update_count":255}
I20260812 06:16:58.761574 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f): perf score=1.000000
I20260812 06:16:58.769461 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.008s	user 0.006s	sys 0.000s Metrics: {"bytes_written":2010377,"delete_count":0,"lbm_write_time_us":2530,"lbm_writes_lt_1ms":52,"reinsert_count":0,"update_count":245}
I20260812 06:16:58.769939 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling MajorDeltaCompactionOp(dec4246709a24903a882ac6e1ff1f18f): perf score=1.000000
I20260812 06:16:58.975952 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: MajorDeltaCompactionOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.206s	user 0.151s	sys 0.047s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28795316,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":564,"lbm_read_time_us":14792,"lbm_reads_lt_1ms":674,"lbm_write_time_us":34029,"lbm_writes_lt_1ms":643,"mutex_wait_us":27,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":5248,"thread_start_us":86,"threads_started":1,"update_count":3000}
I20260812 06:16:58.976511 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f): perf score=14.095187
I20260812 06:16:59.035454 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.059s	user 0.028s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20676,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:59.036047 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f): perf score=2.188937
I20260812 06:16:59.050678 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5419,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:59.051268 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling MajorDeltaCompactionOp(dec4246709a24903a882ac6e1ff1f18f): perf score=1.000000
I20260812 06:16:59.212258 11286 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.168s	user 1.779s	sys 0.159s
I20260812 06:16:59.216598 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: MajorDeltaCompactionOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.165s	user 0.113s	sys 0.051s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24692758,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":531,"lbm_read_time_us":13636,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27593,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2500}
I20260812 06:16:59.218925 11447 maintenance_manager.cc:419] P 3092d69752ae4e1fad5e678a27bd9d1e: Scheduling FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f): perf score=10.126437
I20260812 06:16:59.238173 11286 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.025s	user 0.001s	sys 0.000s
I20260812 06:16:59.238904 11286 tablet_server.cc:179] TabletServer@127.11.5.129:0 shutting down...
I20260812 06:16:59.254524 11387 maintenance_manager.cc:643] P 3092d69752ae4e1fad5e678a27bd9d1e: FlushDeltaMemStoresOp(dec4246709a24903a882ac6e1ff1f18f) complete. Timing: real 0.035s	user 0.021s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15304,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:59.255220 11286 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:16:59.255643 11286 tablet_replica.cc:333] T dec4246709a24903a882ac6e1ff1f18f P 3092d69752ae4e1fad5e678a27bd9d1e: stopping tablet replica
I20260812 06:16:59.255908 11286 raft_consensus.cc:2243] T dec4246709a24903a882ac6e1ff1f18f P 3092d69752ae4e1fad5e678a27bd9d1e [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:59.256125 11286 raft_consensus.cc:2272] T dec4246709a24903a882ac6e1ff1f18f P 3092d69752ae4e1fad5e678a27bd9d1e [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:59.272270 11286 tablet_server.cc:196] TabletServer@127.11.5.129:0 shutdown complete.
I20260812 06:16:59.277714 11286 master.cc:562] Master@127.11.5.190:33317 shutting down...
I20260812 06:16:59.281798 11286 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 458ae5905b6c40e99143115890475772 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:59.282012 11286 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 458ae5905b6c40e99143115890475772 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:59.282094 11286 tablet_replica.cc:333] T 00000000000000000000000000000000 P 458ae5905b6c40e99143115890475772: stopping tablet replica
I20260812 06:16:59.295480 11286 master.cc:584] Master@127.11.5.190:33317 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5629 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:16:59.374980 11286 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.11.5.190:33923
I20260812 06:16:59.375357 11286 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:59.377727 11478 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:59.377727 11481 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:59.377879 11286 server_base.cc:1061] running on GCE node
W20260812 06:16:59.378177 11479 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:59.378391 11286 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:59.378451 11286 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:59.378480 11286 hybrid_clock.cc:648] HybridClock initialized: now 1786515419378480 us; error 0 us; skew 500 ppm
I20260812 06:16:59.379359 11286 webserver.cc:533] Webserver started at http://127.11.5.190:46151/ using document root <none> and password file <none>
I20260812 06:16:59.379536 11286 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:59.379638 11286 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:59.379724 11286 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:59.380177 11286 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413725926-11286-0/minicluster-data/master-0-root/instance:
uuid: "38924f671be54f71b3b130c549c5d4bf"
format_stamp: "Formatted at 2026-08-12 06:16:59 on dist-test-slave-f7th"
I20260812 06:16:59.382016 11286 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:16:59.383080 11486 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:59.383380 11286 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:59.383499 11286 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413725926-11286-0/minicluster-data/master-0-root
uuid: "38924f671be54f71b3b130c549c5d4bf"
format_stamp: "Formatted at 2026-08-12 06:16:59 on dist-test-slave-f7th"
I20260812 06:16:59.383574 11286 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413725926-11286-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413725926-11286-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413725926-11286-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:59.397781 11286 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:59.398229 11286 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:59.403538 11286 rpc_server.cc:307] RPC server started. Bound to: 127.11.5.190:33923
I20260812 06:16:59.406577 11538 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.11.5.190:33923 every 8 connection(s)
I20260812 06:16:59.407083 11539 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:59.408938 11539 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 38924f671be54f71b3b130c549c5d4bf: Bootstrap starting.
I20260812 06:16:59.409706 11539 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 38924f671be54f71b3b130c549c5d4bf: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:59.410709 11539 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 38924f671be54f71b3b130c549c5d4bf: No bootstrap required, opened a new log
I20260812 06:16:59.411082 11539 raft_consensus.cc:359] T 00000000000000000000000000000000 P 38924f671be54f71b3b130c549c5d4bf [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "38924f671be54f71b3b130c549c5d4bf" member_type: VOTER }
I20260812 06:16:59.411190 11539 raft_consensus.cc:385] T 00000000000000000000000000000000 P 38924f671be54f71b3b130c549c5d4bf [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:59.411226 11539 raft_consensus.cc:740] T 00000000000000000000000000000000 P 38924f671be54f71b3b130c549c5d4bf [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 38924f671be54f71b3b130c549c5d4bf, State: Initialized, Role: FOLLOWER
I20260812 06:16:59.411360 11539 consensus_queue.cc:260] T 00000000000000000000000000000000 P 38924f671be54f71b3b130c549c5d4bf [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: "38924f671be54f71b3b130c549c5d4bf" member_type: VOTER }
I20260812 06:16:59.411430 11539 raft_consensus.cc:399] T 00000000000000000000000000000000 P 38924f671be54f71b3b130c549c5d4bf [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:59.411470 11539 raft_consensus.cc:493] T 00000000000000000000000000000000 P 38924f671be54f71b3b130c549c5d4bf [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:59.411517 11539 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 38924f671be54f71b3b130c549c5d4bf [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:59.412218 11539 raft_consensus.cc:515] T 00000000000000000000000000000000 P 38924f671be54f71b3b130c549c5d4bf [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "38924f671be54f71b3b130c549c5d4bf" member_type: VOTER }
I20260812 06:16:59.412345 11539 leader_election.cc:304] T 00000000000000000000000000000000 P 38924f671be54f71b3b130c549c5d4bf [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: 38924f671be54f71b3b130c549c5d4bf; no voters: 
I20260812 06:16:59.412521 11539 leader_election.cc:290] T 00000000000000000000000000000000 P 38924f671be54f71b3b130c549c5d4bf [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:59.412647 11542 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 38924f671be54f71b3b130c549c5d4bf [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:59.412833 11542 raft_consensus.cc:697] T 00000000000000000000000000000000 P 38924f671be54f71b3b130c549c5d4bf [term 1 LEADER]: Becoming Leader. State: Replica: 38924f671be54f71b3b130c549c5d4bf, State: Running, Role: LEADER
I20260812 06:16:59.413003 11539 sys_catalog.cc:565] T 00000000000000000000000000000000 P 38924f671be54f71b3b130c549c5d4bf [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:59.413017 11542 consensus_queue.cc:237] T 00000000000000000000000000000000 P 38924f671be54f71b3b130c549c5d4bf [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: "38924f671be54f71b3b130c549c5d4bf" member_type: VOTER }
I20260812 06:16:59.413511 11544 sys_catalog.cc:455] T 00000000000000000000000000000000 P 38924f671be54f71b3b130c549c5d4bf [sys.catalog]: SysCatalogTable state changed. Reason: New leader 38924f671be54f71b3b130c549c5d4bf. Latest consensus state: current_term: 1 leader_uuid: "38924f671be54f71b3b130c549c5d4bf" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "38924f671be54f71b3b130c549c5d4bf" member_type: VOTER } }
I20260812 06:16:59.413599 11544 sys_catalog.cc:458] T 00000000000000000000000000000000 P 38924f671be54f71b3b130c549c5d4bf [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:59.413522 11543 sys_catalog.cc:455] T 00000000000000000000000000000000 P 38924f671be54f71b3b130c549c5d4bf [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "38924f671be54f71b3b130c549c5d4bf" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "38924f671be54f71b3b130c549c5d4bf" member_type: VOTER } }
I20260812 06:16:59.413640 11543 sys_catalog.cc:458] T 00000000000000000000000000000000 P 38924f671be54f71b3b130c549c5d4bf [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:59.413849 11548 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:59.414683 11548 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:59.414871 11286 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:59.416569 11548 catalog_manager.cc:1383] Generated new cluster ID: 9a83f8a52ce04e2890b53a85ea2f1603
I20260812 06:16:59.416625 11548 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:59.433017 11548 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:59.433590 11548 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:59.439967 11548 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 38924f671be54f71b3b130c549c5d4bf: Generated new TSK 0
I20260812 06:16:59.440171 11548 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:59.447346 11286 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:16:59.449491 11286 server_base.cc:1061] running on GCE node
W20260812 06:16:59.449498 11563 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:59.449617 11560 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:59.449666 11561 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:59.449950 11286 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:59.449994 11286 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:59.450009 11286 hybrid_clock.cc:648] HybridClock initialized: now 1786515419450009 us; error 0 us; skew 500 ppm
I20260812 06:16:59.450881 11286 webserver.cc:533] Webserver started at http://127.11.5.129:39181/ using document root <none> and password file <none>
I20260812 06:16:59.451041 11286 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:59.451088 11286 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:59.451159 11286 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:59.451568 11286 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413725926-11286-0/minicluster-data/ts-0-root/instance:
uuid: "7f68ecacb430468aae5b179cbe57e4f4"
format_stamp: "Formatted at 2026-08-12 06:16:59 on dist-test-slave-f7th"
I20260812 06:16:59.453125 11286 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:59.454196 11568 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:59.454530 11286 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:59.454627 11286 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413725926-11286-0/minicluster-data/ts-0-root
uuid: "7f68ecacb430468aae5b179cbe57e4f4"
format_stamp: "Formatted at 2026-08-12 06:16:59 on dist-test-slave-f7th"
I20260812 06:16:59.454713 11286 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413725926-11286-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413725926-11286-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413725926-11286-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:59.463378 11286 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:59.463812 11286 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:59.464092 11286 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:59.464540 11286 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:59.464582 11286 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:59.464632 11286 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:59.464659 11286 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:59.468686 11286 rpc_server.cc:307] RPC server started. Bound to: 127.11.5.129:45571
I20260812 06:16:59.469115 11631 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.11.5.129:45571 every 8 connection(s)
I20260812 06:16:59.477068 11632 heartbeater.cc:344] Connected to a master server at 127.11.5.190:33923
I20260812 06:16:59.477193 11632 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:59.477438 11632 heartbeater.cc:507] Master 127.11.5.190:33923 requested a full tablet report, sending...
I20260812 06:16:59.478142 11503 ts_manager.cc:194] Registered new tserver with Master: 7f68ecacb430468aae5b179cbe57e4f4 (127.11.5.129:45571)
I20260812 06:16:59.478178 11286 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.008945851s
I20260812 06:16:59.479249 11503 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:60056
I20260812 06:16:59.485841 11503 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:60058:
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:59.494515 11596 tablet_service.cc:1511] Processing CreateTablet for tablet 7b7270f61d5c43238a5f215a7239526c (DEFAULT_TABLE table=heavy-update-compaction-test [id=30fde2b5108b495f86341f9b722e73b2]), partition=
I20260812 06:16:59.494829 11596 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 7b7270f61d5c43238a5f215a7239526c. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:59.497380 11644 tablet_bootstrap.cc:492] T 7b7270f61d5c43238a5f215a7239526c P 7f68ecacb430468aae5b179cbe57e4f4: Bootstrap starting.
I20260812 06:16:59.498261 11644 tablet_bootstrap.cc:654] T 7b7270f61d5c43238a5f215a7239526c P 7f68ecacb430468aae5b179cbe57e4f4: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:59.499347 11644 tablet_bootstrap.cc:492] T 7b7270f61d5c43238a5f215a7239526c P 7f68ecacb430468aae5b179cbe57e4f4: No bootstrap required, opened a new log
I20260812 06:16:59.499431 11644 ts_tablet_manager.cc:1403] T 7b7270f61d5c43238a5f215a7239526c P 7f68ecacb430468aae5b179cbe57e4f4: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:16:59.499938 11644 raft_consensus.cc:359] T 7b7270f61d5c43238a5f215a7239526c P 7f68ecacb430468aae5b179cbe57e4f4 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7f68ecacb430468aae5b179cbe57e4f4" member_type: VOTER last_known_addr { host: "127.11.5.129" port: 45571 } }
I20260812 06:16:59.500037 11644 raft_consensus.cc:385] T 7b7270f61d5c43238a5f215a7239526c P 7f68ecacb430468aae5b179cbe57e4f4 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:59.500069 11644 raft_consensus.cc:740] T 7b7270f61d5c43238a5f215a7239526c P 7f68ecacb430468aae5b179cbe57e4f4 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 7f68ecacb430468aae5b179cbe57e4f4, State: Initialized, Role: FOLLOWER
I20260812 06:16:59.500272 11644 consensus_queue.cc:260] T 7b7270f61d5c43238a5f215a7239526c P 7f68ecacb430468aae5b179cbe57e4f4 [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: "7f68ecacb430468aae5b179cbe57e4f4" member_type: VOTER last_known_addr { host: "127.11.5.129" port: 45571 } }
I20260812 06:16:59.500379 11644 raft_consensus.cc:399] T 7b7270f61d5c43238a5f215a7239526c P 7f68ecacb430468aae5b179cbe57e4f4 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:59.500418 11644 raft_consensus.cc:493] T 7b7270f61d5c43238a5f215a7239526c P 7f68ecacb430468aae5b179cbe57e4f4 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:59.500468 11644 raft_consensus.cc:3060] T 7b7270f61d5c43238a5f215a7239526c P 7f68ecacb430468aae5b179cbe57e4f4 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:59.501186 11644 raft_consensus.cc:515] T 7b7270f61d5c43238a5f215a7239526c P 7f68ecacb430468aae5b179cbe57e4f4 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7f68ecacb430468aae5b179cbe57e4f4" member_type: VOTER last_known_addr { host: "127.11.5.129" port: 45571 } }
I20260812 06:16:59.501312 11644 leader_election.cc:304] T 7b7270f61d5c43238a5f215a7239526c P 7f68ecacb430468aae5b179cbe57e4f4 [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: 7f68ecacb430468aae5b179cbe57e4f4; no voters: 
I20260812 06:16:59.501502 11644 leader_election.cc:290] T 7b7270f61d5c43238a5f215a7239526c P 7f68ecacb430468aae5b179cbe57e4f4 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:59.501636 11646 raft_consensus.cc:2804] T 7b7270f61d5c43238a5f215a7239526c P 7f68ecacb430468aae5b179cbe57e4f4 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:59.501870 11632 heartbeater.cc:499] Master 127.11.5.190:33923 was elected leader, sending a full tablet report...
I20260812 06:16:59.501868 11644 ts_tablet_manager.cc:1434] T 7b7270f61d5c43238a5f215a7239526c P 7f68ecacb430468aae5b179cbe57e4f4: Time spent starting tablet: real 0.002s	user 0.000s	sys 0.003s
I20260812 06:16:59.501869 11646 raft_consensus.cc:697] T 7b7270f61d5c43238a5f215a7239526c P 7f68ecacb430468aae5b179cbe57e4f4 [term 1 LEADER]: Becoming Leader. State: Replica: 7f68ecacb430468aae5b179cbe57e4f4, State: Running, Role: LEADER
I20260812 06:16:59.502332 11646 consensus_queue.cc:237] T 7b7270f61d5c43238a5f215a7239526c P 7f68ecacb430468aae5b179cbe57e4f4 [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: "7f68ecacb430468aae5b179cbe57e4f4" member_type: VOTER last_known_addr { host: "127.11.5.129" port: 45571 } }
I20260812 06:16:59.503648 11503 catalog_manager.cc:5719] T 7b7270f61d5c43238a5f215a7239526c P 7f68ecacb430468aae5b179cbe57e4f4 reported cstate change: term changed from 0 to 1, leader changed from <none> to 7f68ecacb430468aae5b179cbe57e4f4 (127.11.5.129). New cstate: current_term: 1 leader_uuid: "7f68ecacb430468aae5b179cbe57e4f4" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7f68ecacb430468aae5b179cbe57e4f4" member_type: VOTER last_known_addr { host: "127.11.5.129" port: 45571 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:59.562829 11286 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.053s	user 0.012s	sys 0.010s
I20260812 06:16:59.719828 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling FlushMRSOp(7b7270f61d5c43238a5f215a7239526c): perf score=19.054940
I20260812 06:16:59.852843 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: FlushMRSOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.133s	user 0.103s	sys 0.028s Metrics: {"bytes_written":9148635,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":70,"dirs.run_cpu_time_us":183,"dirs.run_wall_time_us":950,"drs_written":1,"lbm_read_time_us":41,"lbm_reads_lt_1ms":4,"lbm_write_time_us":32417,"lbm_writes_lt_1ms":680,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1115}
I20260812 06:16:59.853600 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling LogGCOp(7b7270f61d5c43238a5f215a7239526c): free 20743880 bytes of WAL
I20260812 06:16:59.853879 11573 log_reader.cc:385] T 7b7270f61d5c43238a5f215a7239526c: removed 2 log segments from log reader
I20260812 06:16:59.853950 11573 log.cc:1079] T 7b7270f61d5c43238a5f215a7239526c P 7f68ecacb430468aae5b179cbe57e4f4: Deleting log segment in path: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413725926-11286-0/minicluster-data/ts-0-root/wals/7b7270f61d5c43238a5f215a7239526c/wal-000000001 (ops 1-6)
I20260812 06:16:59.854056 11573 log.cc:1079] T 7b7270f61d5c43238a5f215a7239526c P 7f68ecacb430468aae5b179cbe57e4f4: Deleting log segment in path: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413725926-11286-0/minicluster-data/ts-0-root/wals/7b7270f61d5c43238a5f215a7239526c/wal-000000002 (ops 7-11)
I20260812 06:16:59.859212 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: LogGCOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.005s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:16:59.859813 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c): perf score=1.196750
I20260812 06:16:59.882007 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.022s	user 0.009s	sys 0.007s Metrics: {"bytes_written":3159080,"delete_count":0,"lbm_write_time_us":4127,"lbm_writes_lt_1ms":80,"reinsert_count":0,"update_count":385}
I20260812 06:16:59.882884 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling MajorDeltaCompactionOp(7b7270f61d5c43238a5f215a7239526c): perf score=1.000000
I20260812 06:17:00.027232 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: MajorDeltaCompactionOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.143s	user 0.095s	sys 0.045s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16569843,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":633,"lbm_read_time_us":9787,"lbm_reads_lt_1ms":364,"lbm_write_time_us":20234,"lbm_writes_lt_1ms":343,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":3328,"thread_start_us":308,"threads_started":5,"update_count":1500}
I20260812 06:17:00.027866 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling UndoDeltaBlockGCOp(7b7270f61d5c43238a5f215a7239526c): 16411394 bytes on disk
I20260812 06:17:00.028342 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: UndoDeltaBlockGCOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4}
I20260812 06:17:00.028837 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c): perf score=11.118625
I20260812 06:17:00.078761 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.049s	user 0.025s	sys 0.016s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":21334,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:17:00.079337 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c): perf score=2.188937
I20260812 06:17:00.093918 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.014s	user 0.005s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5421,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:00.094417 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c): perf score=2.188937
I20260812 06:17:00.108630 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.014s	user 0.012s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4968,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:00.109153 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling MajorDeltaCompactionOp(7b7270f61d5c43238a5f215a7239526c): perf score=1.000000
I20260812 06:17:00.282207 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: MajorDeltaCompactionOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.173s	user 0.127s	sys 0.041s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":499,"lbm_read_time_us":11309,"lbm_reads_lt_1ms":565,"lbm_write_time_us":31522,"lbm_writes_lt_1ms":543,"mutex_wait_us":311,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":15488,"update_count":2500}
I20260812 06:17:00.282809 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c): perf score=14.095187
I20260812 06:17:00.335870 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.052s	user 0.040s	sys 0.008s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":20606,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:00.336366 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c): perf score=2.188937
I20260812 06:17:00.351171 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.015s	user 0.009s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5223,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:00.351735 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling MajorDeltaCompactionOp(7b7270f61d5c43238a5f215a7239526c): perf score=1.000000
I20260812 06:17:00.496727 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: MajorDeltaCompactionOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.145s	user 0.108s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":189,"lbm_read_time_us":9503,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27074,"lbm_writes_lt_1ms":543,"mutex_wait_us":82,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5376,"update_count":2500}
I20260812 06:17:00.497677 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c): perf score=10.126437
I20260812 06:17:00.528326 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.030s	user 0.014s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13148,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:00.528767 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling MajorDeltaCompactionOp(7b7270f61d5c43238a5f215a7239526c): perf score=1.000000
I20260812 06:17:00.653358 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: MajorDeltaCompactionOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.124s	user 0.070s	sys 0.048s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569746,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":128,"lbm_read_time_us":8946,"lbm_reads_lt_1ms":363,"lbm_write_time_us":17489,"lbm_writes_lt_1ms":343,"mutex_wait_us":28,"peak_mem_usage":38262756,"reinsert_count":0,"update_count":1500}
I20260812 06:17:00.653826 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c): perf score=10.126437
I20260812 06:17:00.691478 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.038s	user 0.019s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14323,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:00.692106 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling MajorDeltaCompactionOp(7b7270f61d5c43238a5f215a7239526c): perf score=1.000000
I20260812 06:17:00.816483 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: MajorDeltaCompactionOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.124s	user 0.099s	sys 0.020s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569746,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":406,"lbm_read_time_us":7955,"lbm_reads_lt_1ms":363,"lbm_write_time_us":22287,"lbm_writes_lt_1ms":343,"mutex_wait_us":267,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":11008,"update_count":1500}
I20260812 06:17:00.817020 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c): perf score=10.126437
I20260812 06:17:00.856096 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.039s	user 0.024s	sys 0.013s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16532,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:00.859450 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling MajorDeltaCompactionOp(7b7270f61d5c43238a5f215a7239526c): perf score=1.000000
I20260812 06:17:00.983074 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: MajorDeltaCompactionOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.123s	user 0.102s	sys 0.021s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569747,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":131,"lbm_read_time_us":6744,"lbm_reads_lt_1ms":363,"lbm_write_time_us":23804,"lbm_writes_lt_1ms":343,"mutex_wait_us":43,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":1500}
I20260812 06:17:00.983686 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c): perf score=10.126437
I20260812 06:17:01.035413 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.052s	user 0.030s	sys 0.009s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16979,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:01.036042 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c): perf score=2.188937
I20260812 06:17:01.048373 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.012s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4470,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:01.048910 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling MajorDeltaCompactionOp(7b7270f61d5c43238a5f215a7239526c): perf score=1.000000
I20260812 06:17:01.189465 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: MajorDeltaCompactionOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.140s	user 0.108s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":865,"lbm_read_time_us":9708,"lbm_reads_lt_1ms":468,"lbm_write_time_us":24589,"lbm_writes_lt_1ms":443,"mutex_wait_us":225,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2944,"update_count":2000}
I20260812 06:17:01.191289 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c): perf score=10.126437
I20260812 06:17:01.238557 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.047s	user 0.028s	sys 0.003s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":14321,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:01.239137 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c): perf score=2.188937
I20260812 06:17:01.253947 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.015s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5290,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:01.258028 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling FlushMRSOp(7b7270f61d5c43238a5f215a7239526c): perf score=1.000000
I20260812 06:17:01.290516 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: FlushMRSOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.032s	user 0.027s	sys 0.003s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":65,"dirs.run_cpu_time_us":174,"dirs.run_wall_time_us":1132,"drs_written":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1437,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:17:01.291150 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling LogGCOp(7b7270f61d5c43238a5f215a7239526c): free 120553325 bytes of WAL
I20260812 06:17:01.291357 11573 log_reader.cc:385] T 7b7270f61d5c43238a5f215a7239526c: removed 12 log segments from log reader
I20260812 06:17:01.291397 11573 log.cc:1079] T 7b7270f61d5c43238a5f215a7239526c P 7f68ecacb430468aae5b179cbe57e4f4: Deleting log segment in path: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413725926-11286-0/minicluster-data/ts-0-root/wals/7b7270f61d5c43238a5f215a7239526c/wal-000000003 (ops 12-16)
I20260812 06:17:01.291436 11573 log.cc:1079] T 7b7270f61d5c43238a5f215a7239526c P 7f68ecacb430468aae5b179cbe57e4f4: Deleting log segment in path: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413725926-11286-0/minicluster-data/ts-0-root/wals/7b7270f61d5c43238a5f215a7239526c/wal-000000004 (ops 17-21)
I20260812 06:17:01.291471 11573 log.cc:1079] T 7b7270f61d5c43238a5f215a7239526c P 7f68ecacb430468aae5b179cbe57e4f4: Deleting log segment in path: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413725926-11286-0/minicluster-data/ts-0-root/wals/7b7270f61d5c43238a5f215a7239526c/wal-000000005 (ops 22-26)
I20260812 06:17:01.291504 11573 log.cc:1079] T 7b7270f61d5c43238a5f215a7239526c P 7f68ecacb430468aae5b179cbe57e4f4: Deleting log segment in path: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413725926-11286-0/minicluster-data/ts-0-root/wals/7b7270f61d5c43238a5f215a7239526c/wal-000000006 (ops 27-30)
I20260812 06:17:01.291534 11573 log.cc:1079] T 7b7270f61d5c43238a5f215a7239526c P 7f68ecacb430468aae5b179cbe57e4f4: Deleting log segment in path: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413725926-11286-0/minicluster-data/ts-0-root/wals/7b7270f61d5c43238a5f215a7239526c/wal-000000007 (ops 31-35)
I20260812 06:17:01.291563 11573 log.cc:1079] T 7b7270f61d5c43238a5f215a7239526c P 7f68ecacb430468aae5b179cbe57e4f4: Deleting log segment in path: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413725926-11286-0/minicluster-data/ts-0-root/wals/7b7270f61d5c43238a5f215a7239526c/wal-000000008 (ops 36-40)
I20260812 06:17:01.291618 11573 log.cc:1079] T 7b7270f61d5c43238a5f215a7239526c P 7f68ecacb430468aae5b179cbe57e4f4: Deleting log segment in path: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413725926-11286-0/minicluster-data/ts-0-root/wals/7b7270f61d5c43238a5f215a7239526c/wal-000000009 (ops 41-45)
I20260812 06:17:01.291656 11573 log.cc:1079] T 7b7270f61d5c43238a5f215a7239526c P 7f68ecacb430468aae5b179cbe57e4f4: Deleting log segment in path: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413725926-11286-0/minicluster-data/ts-0-root/wals/7b7270f61d5c43238a5f215a7239526c/wal-000000010 (ops 46-50)
I20260812 06:17:01.291688 11573 log.cc:1079] T 7b7270f61d5c43238a5f215a7239526c P 7f68ecacb430468aae5b179cbe57e4f4: Deleting log segment in path: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413725926-11286-0/minicluster-data/ts-0-root/wals/7b7270f61d5c43238a5f215a7239526c/wal-000000011 (ops 51-55)
I20260812 06:17:01.291720 11573 log.cc:1079] T 7b7270f61d5c43238a5f215a7239526c P 7f68ecacb430468aae5b179cbe57e4f4: Deleting log segment in path: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413725926-11286-0/minicluster-data/ts-0-root/wals/7b7270f61d5c43238a5f215a7239526c/wal-000000012 (ops 56-60)
I20260812 06:17:01.291754 11573 log.cc:1079] T 7b7270f61d5c43238a5f215a7239526c P 7f68ecacb430468aae5b179cbe57e4f4: Deleting log segment in path: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413725926-11286-0/minicluster-data/ts-0-root/wals/7b7270f61d5c43238a5f215a7239526c/wal-000000013 (ops 61-64)
I20260812 06:17:01.291785 11573 log.cc:1079] T 7b7270f61d5c43238a5f215a7239526c P 7f68ecacb430468aae5b179cbe57e4f4: Deleting log segment in path: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413725926-11286-0/minicluster-data/ts-0-root/wals/7b7270f61d5c43238a5f215a7239526c/wal-000000014 (ops 65-69)
I20260812 06:17:01.316496 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: LogGCOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.025s	user 0.005s	sys 0.019s Metrics: {}
I20260812 06:17:01.317049 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c): perf score=3.181125
I20260812 06:17:01.331071 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":5333,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:01.331552 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c): perf score=2.188937
I20260812 06:17:01.345517 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.014s	user 0.007s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4768,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:01.345985 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling UndoDeltaBlockGCOp(7b7270f61d5c43238a5f215a7239526c): 473 bytes on disk
I20260812 06:17:01.346396 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: UndoDeltaBlockGCOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":71,"lbm_reads_lt_1ms":4}
I20260812 06:17:01.346839 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling MajorDeltaCompactionOp(7b7270f61d5c43238a5f215a7239526c): perf score=1.000000
I20260812 06:17:01.534999 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: MajorDeltaCompactionOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.188s	user 0.151s	sys 0.025s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877331,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":376,"lbm_read_time_us":11612,"lbm_reads_lt_1ms":674,"lbm_write_time_us":42854,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":642,"mutex_wait_us":4,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":92,"threads_started":1,"update_count":3000}
I20260812 06:17:01.535640 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c): perf score=14.095187
I20260812 06:17:01.593142 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.057s	user 0.037s	sys 0.009s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20811,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:01.593683 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c): perf score=2.188937
I20260812 06:17:01.606145 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4703,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:01.606665 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling MajorDeltaCompactionOp(7b7270f61d5c43238a5f215a7239526c): perf score=1.000000
I20260812 06:17:01.772945 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: MajorDeltaCompactionOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.166s	user 0.134s	sys 0.032s 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":118,"lbm_read_time_us":11106,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31815,"lbm_writes_lt_1ms":543,"mutex_wait_us":36,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2500}
I20260812 06:17:01.773576 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c): perf score=11.118625
I20260812 06:17:01.807672 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.034s	user 0.030s	sys 0.003s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":14250,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:01.808265 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c): perf score=2.188937
I20260812 06:17:01.821049 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4706,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:01.821506 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling MajorDeltaCompactionOp(7b7270f61d5c43238a5f215a7239526c): perf score=1.000000
I20260812 06:17:01.960132 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: MajorDeltaCompactionOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.138s	user 0.107s	sys 0.031s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672269,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":476,"lbm_read_time_us":9750,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25385,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":2000}
I20260812 06:17:01.960891 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c): perf score=10.126437
I20260812 06:17:02.011502 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.050s	user 0.017s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15641,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:02.012136 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c): perf score=2.188937
I20260812 06:17:02.025540 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5071,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:02.026110 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling MajorDeltaCompactionOp(7b7270f61d5c43238a5f215a7239526c): perf score=1.000000
I20260812 06:17:02.151192 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: MajorDeltaCompactionOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.123s	user 0.110s	sys 0.013s 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":219,"lbm_read_time_us":8314,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22644,"lbm_writes_lt_1ms":443,"mutex_wait_us":28,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9984,"update_count":2000}
I20260812 06:17:02.151708 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c): perf score=10.126437
I20260812 06:17:02.209226 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.057s	user 0.016s	sys 0.028s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14763,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:02.209764 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c): perf score=2.188937
I20260812 06:17:02.222563 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.013s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4834,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:02.223070 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling MajorDeltaCompactionOp(7b7270f61d5c43238a5f215a7239526c): perf score=1.000000
I20260812 06:17:02.372790 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: MajorDeltaCompactionOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.150s	user 0.096s	sys 0.052s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":168,"lbm_read_time_us":9930,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23458,"lbm_writes_lt_1ms":443,"mutex_wait_us":1,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:17:02.373311 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c): perf score=10.126437
I20260812 06:17:02.413061 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.040s	user 0.034s	sys 0.004s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":16661,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:02.413578 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling MajorDeltaCompactionOp(7b7270f61d5c43238a5f215a7239526c): perf score=1.000000
I20260812 06:17:02.528887 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: MajorDeltaCompactionOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.114s	user 0.094s	sys 0.020s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569748,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":211,"lbm_read_time_us":6427,"lbm_reads_lt_1ms":363,"lbm_write_time_us":20929,"lbm_writes_lt_1ms":343,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":1500}
I20260812 06:17:02.530793 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c): perf score=10.126437
I20260812 06:17:02.575834 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.045s	user 0.027s	sys 0.008s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":14315,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":1500}
I20260812 06:17:02.576359 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c): perf score=2.188937
I20260812 06:17:02.589690 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.013s	user 0.004s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4888,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:02.590248 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling MajorDeltaCompactionOp(7b7270f61d5c43238a5f215a7239526c): perf score=1.000000
I20260812 06:17:02.727662 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: MajorDeltaCompactionOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.137s	user 0.117s	sys 0.019s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":684,"lbm_read_time_us":8814,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26182,"lbm_writes_lt_1ms":443,"mutex_wait_us":34,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14080,"update_count":2000}
I20260812 06:17:02.728238 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c): perf score=10.126437
I20260812 06:17:02.782316 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.054s	user 0.026s	sys 0.023s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":17512,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:02.782949 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c): perf score=2.188937
I20260812 06:17:02.796530 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.013s	user 0.003s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5111,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:02.797010 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling FlushMRSOp(7b7270f61d5c43238a5f215a7239526c): perf score=1.000000
I20260812 06:17:02.843365 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: FlushMRSOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.046s	user 0.026s	sys 0.006s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":2872,"dirs.run_cpu_time_us":184,"dirs.run_wall_time_us":1358,"drs_written":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1855,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:17:02.844128 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling LogGCOp(7b7270f61d5c43238a5f215a7239526c): free 120553380 bytes of WAL
I20260812 06:17:02.844372 11573 log_reader.cc:385] T 7b7270f61d5c43238a5f215a7239526c: removed 12 log segments from log reader
I20260812 06:17:02.844419 11573 log.cc:1079] T 7b7270f61d5c43238a5f215a7239526c P 7f68ecacb430468aae5b179cbe57e4f4: Deleting log segment in path: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413725926-11286-0/minicluster-data/ts-0-root/wals/7b7270f61d5c43238a5f215a7239526c/wal-000000015 (ops 70-74)
I20260812 06:17:02.844453 11573 log.cc:1079] T 7b7270f61d5c43238a5f215a7239526c P 7f68ecacb430468aae5b179cbe57e4f4: Deleting log segment in path: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413725926-11286-0/minicluster-data/ts-0-root/wals/7b7270f61d5c43238a5f215a7239526c/wal-000000016 (ops 75-79)
I20260812 06:17:02.844571 11573 log.cc:1079] T 7b7270f61d5c43238a5f215a7239526c P 7f68ecacb430468aae5b179cbe57e4f4: Deleting log segment in path: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413725926-11286-0/minicluster-data/ts-0-root/wals/7b7270f61d5c43238a5f215a7239526c/wal-000000017 (ops 80-84)
I20260812 06:17:02.844659 11573 log.cc:1079] T 7b7270f61d5c43238a5f215a7239526c P 7f68ecacb430468aae5b179cbe57e4f4: Deleting log segment in path: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413725926-11286-0/minicluster-data/ts-0-root/wals/7b7270f61d5c43238a5f215a7239526c/wal-000000018 (ops 85-88)
I20260812 06:17:02.844687 11573 log.cc:1079] T 7b7270f61d5c43238a5f215a7239526c P 7f68ecacb430468aae5b179cbe57e4f4: Deleting log segment in path: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413725926-11286-0/minicluster-data/ts-0-root/wals/7b7270f61d5c43238a5f215a7239526c/wal-000000019 (ops 89-93)
I20260812 06:17:02.844717 11573 log.cc:1079] T 7b7270f61d5c43238a5f215a7239526c P 7f68ecacb430468aae5b179cbe57e4f4: Deleting log segment in path: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413725926-11286-0/minicluster-data/ts-0-root/wals/7b7270f61d5c43238a5f215a7239526c/wal-000000020 (ops 94-98)
I20260812 06:17:02.844741 11573 log.cc:1079] T 7b7270f61d5c43238a5f215a7239526c P 7f68ecacb430468aae5b179cbe57e4f4: Deleting log segment in path: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413725926-11286-0/minicluster-data/ts-0-root/wals/7b7270f61d5c43238a5f215a7239526c/wal-000000021 (ops 99-103)
I20260812 06:17:02.844774 11573 log.cc:1079] T 7b7270f61d5c43238a5f215a7239526c P 7f68ecacb430468aae5b179cbe57e4f4: Deleting log segment in path: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413725926-11286-0/minicluster-data/ts-0-root/wals/7b7270f61d5c43238a5f215a7239526c/wal-000000022 (ops 104-108)
I20260812 06:17:02.844803 11573 log.cc:1079] T 7b7270f61d5c43238a5f215a7239526c P 7f68ecacb430468aae5b179cbe57e4f4: Deleting log segment in path: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413725926-11286-0/minicluster-data/ts-0-root/wals/7b7270f61d5c43238a5f215a7239526c/wal-000000023 (ops 109-113)
I20260812 06:17:02.844835 11573 log.cc:1079] T 7b7270f61d5c43238a5f215a7239526c P 7f68ecacb430468aae5b179cbe57e4f4: Deleting log segment in path: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413725926-11286-0/minicluster-data/ts-0-root/wals/7b7270f61d5c43238a5f215a7239526c/wal-000000024 (ops 114-118)
I20260812 06:17:02.844869 11573 log.cc:1079] T 7b7270f61d5c43238a5f215a7239526c P 7f68ecacb430468aae5b179cbe57e4f4: Deleting log segment in path: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413725926-11286-0/minicluster-data/ts-0-root/wals/7b7270f61d5c43238a5f215a7239526c/wal-000000025 (ops 119-122)
I20260812 06:17:02.844901 11573 log.cc:1079] T 7b7270f61d5c43238a5f215a7239526c P 7f68ecacb430468aae5b179cbe57e4f4: Deleting log segment in path: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413725926-11286-0/minicluster-data/ts-0-root/wals/7b7270f61d5c43238a5f215a7239526c/wal-000000026 (ops 123-127)
I20260812 06:17:02.867748 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: LogGCOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.023s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:17:02.868472 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling UndoDeltaBlockGCOp(7b7270f61d5c43238a5f215a7239526c): 472 bytes on disk
I20260812 06:17:02.869057 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: UndoDeltaBlockGCOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":74,"lbm_reads_lt_1ms":4}
I20260812 06:17:02.869665 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c): perf score=2.188937
I20260812 06:17:02.893054 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.023s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4757,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:02.893553 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling LogGCOp(7b7270f61d5c43238a5f215a7239526c): free 12018000 bytes of WAL
I20260812 06:17:02.893780 11573 log_reader.cc:385] T 7b7270f61d5c43238a5f215a7239526c: removed 1 log segments from log reader
I20260812 06:17:02.893836 11573 log.cc:1079] T 7b7270f61d5c43238a5f215a7239526c P 7f68ecacb430468aae5b179cbe57e4f4: Deleting log segment in path: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413725926-11286-0/minicluster-data/ts-0-root/wals/7b7270f61d5c43238a5f215a7239526c/wal-000000027 (ops 128-132)
I20260812 06:17:02.897024 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: LogGCOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.003s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:17:02.897594 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c): perf score=2.188937
I20260812 06:17:02.920046 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.022s	user 0.005s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7211,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:02.920691 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling MajorDeltaCompactionOp(7b7270f61d5c43238a5f215a7239526c): perf score=1.000000
I20260812 06:17:03.141096 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: MajorDeltaCompactionOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.220s	user 0.125s	sys 0.087s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877338,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":533,"lbm_read_time_us":13320,"lbm_reads_lt_1ms":666,"lbm_write_time_us":35020,"lbm_writes_lt_1ms":643,"mutex_wait_us":29,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3200,"thread_start_us":75,"threads_started":1,"update_count":3000}
I20260812 06:17:03.147358 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c): perf score=18.063937
I20260812 06:17:03.210888 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.063s	user 0.023s	sys 0.035s Metrics: {"bytes_written":19773881,"delete_count":0,"lbm_write_time_us":24802,"lbm_writes_lt_1ms":485,"reinsert_count":0,"update_count":2410}
I20260812 06:17:03.211349 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c): perf score=3.181125
I20260812 06:17:03.225944 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.014s	user 0.009s	sys 0.003s Metrics: {"bytes_written":4841098,"delete_count":0,"lbm_write_time_us":5463,"lbm_writes_lt_1ms":121,"reinsert_count":0,"update_count":590}
I20260812 06:17:03.226578 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling MajorDeltaCompactionOp(7b7270f61d5c43238a5f215a7239526c): perf score=1.000000
I20260812 06:17:03.439994 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: MajorDeltaCompactionOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.212s	user 0.158s	sys 0.053s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877107,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":220,"lbm_read_time_us":14306,"lbm_reads_lt_1ms":672,"lbm_write_time_us":35073,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1536,"update_count":3000}
I20260812 06:17:03.440644 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c): perf score=14.095187
I20260812 06:17:03.493891 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.051s	user 0.029s	sys 0.012s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":19353,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:03.494437 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c): perf score=2.188937
I20260812 06:17:03.506955 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.012s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4776,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:03.507418 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling MajorDeltaCompactionOp(7b7270f61d5c43238a5f215a7239526c): perf score=1.000000
I20260812 06:17:03.703835 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: MajorDeltaCompactionOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.196s	user 0.135s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1331,"lbm_read_time_us":13478,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30013,"lbm_writes_lt_1ms":543,"mutex_wait_us":652,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4864,"update_count":2500}
I20260812 06:17:03.708047 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c): perf score=14.095187
I20260812 06:17:03.762959 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.055s	user 0.027s	sys 0.013s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18149,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:03.763535 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c): perf score=2.188937
I20260812 06:17:03.776270 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.013s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4828,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:03.776813 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling MajorDeltaCompactionOp(7b7270f61d5c43238a5f215a7239526c): perf score=1.000000
I20260812 06:17:03.973167 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: MajorDeltaCompactionOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.196s	user 0.132s	sys 0.053s 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":766,"lbm_read_time_us":12695,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30030,"lbm_writes_lt_1ms":543,"mutex_wait_us":221,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:17:03.973632 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c): perf score=14.095187
I20260812 06:17:04.040772 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.067s	user 0.036s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21292,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:04.041349 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c): perf score=2.188937
I20260812 06:17:04.056061 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.015s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5523,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:04.056747 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling MajorDeltaCompactionOp(7b7270f61d5c43238a5f215a7239526c): perf score=1.000000
I20260812 06:17:04.254895 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: MajorDeltaCompactionOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.198s	user 0.109s	sys 0.076s 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":507,"lbm_read_time_us":12522,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29815,"lbm_writes_lt_1ms":543,"mutex_wait_us":295,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3200,"update_count":2500}
I20260812 06:17:04.255662 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c): perf score=14.095187
I20260812 06:17:04.324299 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.068s	user 0.024s	sys 0.040s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25359,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:17:04.324847 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c): perf score=2.188937
I20260812 06:17:04.337800 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102660,"delete_count":0,"lbm_write_time_us":4803,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:04.338393 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling FlushMRSOp(7b7270f61d5c43238a5f215a7239526c): perf score=1.000000
I20260812 06:17:04.385771 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: FlushMRSOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.047s	user 0.028s	sys 0.004s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":41,"dirs.run_cpu_time_us":177,"dirs.run_wall_time_us":1400,"drs_written":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1792,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:04.386601 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling LogGCOp(7b7270f61d5c43238a5f215a7239526c): free 108988753 bytes of WAL
I20260812 06:17:04.386971 11573 log_reader.cc:385] T 7b7270f61d5c43238a5f215a7239526c: removed 11 log segments from log reader
I20260812 06:17:04.387027 11573 log.cc:1079] T 7b7270f61d5c43238a5f215a7239526c P 7f68ecacb430468aae5b179cbe57e4f4: Deleting log segment in path: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413725926-11286-0/minicluster-data/ts-0-root/wals/7b7270f61d5c43238a5f215a7239526c/wal-000000028 (ops 133-137)
I20260812 06:17:04.387117 11573 log.cc:1079] T 7b7270f61d5c43238a5f215a7239526c P 7f68ecacb430468aae5b179cbe57e4f4: Deleting log segment in path: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413725926-11286-0/minicluster-data/ts-0-root/wals/7b7270f61d5c43238a5f215a7239526c/wal-000000029 (ops 138-142)
I20260812 06:17:04.387158 11573 log.cc:1079] T 7b7270f61d5c43238a5f215a7239526c P 7f68ecacb430468aae5b179cbe57e4f4: Deleting log segment in path: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413725926-11286-0/minicluster-data/ts-0-root/wals/7b7270f61d5c43238a5f215a7239526c/wal-000000030 (ops 143-146)
I20260812 06:17:04.387225 11573 log.cc:1079] T 7b7270f61d5c43238a5f215a7239526c P 7f68ecacb430468aae5b179cbe57e4f4: Deleting log segment in path: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413725926-11286-0/minicluster-data/ts-0-root/wals/7b7270f61d5c43238a5f215a7239526c/wal-000000031 (ops 147-151)
I20260812 06:17:04.387266 11573 log.cc:1079] T 7b7270f61d5c43238a5f215a7239526c P 7f68ecacb430468aae5b179cbe57e4f4: Deleting log segment in path: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413725926-11286-0/minicluster-data/ts-0-root/wals/7b7270f61d5c43238a5f215a7239526c/wal-000000032 (ops 152-156)
I20260812 06:17:04.387302 11573 log.cc:1079] T 7b7270f61d5c43238a5f215a7239526c P 7f68ecacb430468aae5b179cbe57e4f4: Deleting log segment in path: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413725926-11286-0/minicluster-data/ts-0-root/wals/7b7270f61d5c43238a5f215a7239526c/wal-000000033 (ops 157-161)
I20260812 06:17:04.387336 11573 log.cc:1079] T 7b7270f61d5c43238a5f215a7239526c P 7f68ecacb430468aae5b179cbe57e4f4: Deleting log segment in path: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413725926-11286-0/minicluster-data/ts-0-root/wals/7b7270f61d5c43238a5f215a7239526c/wal-000000034 (ops 162-166)
I20260812 06:17:04.387377 11573 log.cc:1079] T 7b7270f61d5c43238a5f215a7239526c P 7f68ecacb430468aae5b179cbe57e4f4: Deleting log segment in path: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413725926-11286-0/minicluster-data/ts-0-root/wals/7b7270f61d5c43238a5f215a7239526c/wal-000000035 (ops 167-171)
I20260812 06:17:04.387413 11573 log.cc:1079] T 7b7270f61d5c43238a5f215a7239526c P 7f68ecacb430468aae5b179cbe57e4f4: Deleting log segment in path: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413725926-11286-0/minicluster-data/ts-0-root/wals/7b7270f61d5c43238a5f215a7239526c/wal-000000036 (ops 172-176)
I20260812 06:17:04.387449 11573 log.cc:1079] T 7b7270f61d5c43238a5f215a7239526c P 7f68ecacb430468aae5b179cbe57e4f4: Deleting log segment in path: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413725926-11286-0/minicluster-data/ts-0-root/wals/7b7270f61d5c43238a5f215a7239526c/wal-000000037 (ops 177-181)
I20260812 06:17:04.387487 11573 log.cc:1079] T 7b7270f61d5c43238a5f215a7239526c P 7f68ecacb430468aae5b179cbe57e4f4: Deleting log segment in path: /tmp/dist-test-task9LJNdw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413725926-11286-0/minicluster-data/ts-0-root/wals/7b7270f61d5c43238a5f215a7239526c/wal-000000038 (ops 182-186)
I20260812 06:17:04.412703 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: LogGCOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.026s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:17:04.413148 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c): perf score=3.181125
I20260812 06:17:04.434465 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.021s	user 0.002s	sys 0.011s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":5537,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:04.434950 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling UndoDeltaBlockGCOp(7b7270f61d5c43238a5f215a7239526c): 447 bytes on disk
I20260812 06:17:04.435387 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: UndoDeltaBlockGCOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4}
I20260812 06:17:04.436079 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c): perf score=2.188937
I20260812 06:17:04.449792 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.013s	user 0.002s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4727,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:04.450416 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling MajorDeltaCompactionOp(7b7270f61d5c43238a5f215a7239526c): perf score=1.000000
I20260812 06:17:04.707809 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: MajorDeltaCompactionOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.255s	user 0.162s	sys 0.075s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979741,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":821,"dirs.run_cpu_time_us":709,"dirs.run_wall_time_us":4464,"lbm_read_time_us":15398,"lbm_reads_lt_1ms":774,"lbm_write_time_us":37352,"lbm_writes_lt_1ms":743,"mutex_wait_us":300,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":13568,"update_count":3500}
I20260812 06:17:04.708582 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c): perf score=18.063937
I20260812 06:17:04.778221 11286 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.215s	user 1.830s	sys 0.184s
I20260812 06:17:04.782907 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.074s	user 0.025s	sys 0.033s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":28551,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":502,"reinsert_count":0,"update_count":2500}
I20260812 06:17:04.783384 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c): perf score=2.188937
I20260812 06:17:04.795817 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: FlushDeltaMemStoresOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.012s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4678,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:04.796300 11633 maintenance_manager.cc:419] P 7f68ecacb430468aae5b179cbe57e4f4: Scheduling MajorDeltaCompactionOp(7b7270f61d5c43238a5f215a7239526c): perf score=1.000000
I20260812 06:17:04.818339 11286 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.040s	user 0.001s	sys 0.000s
I20260812 06:17:04.818868 11286 tablet_server.cc:179] TabletServer@127.11.5.129:0 shutting down...
I20260812 06:17:04.985316 11573 maintenance_manager.cc:643] P 7f68ecacb430468aae5b179cbe57e4f4: MajorDeltaCompactionOp(7b7270f61d5c43238a5f215a7239526c) complete. Timing: real 0.189s	user 0.118s	sys 0.065s Metrics: {"cfile_cache_hit":30,"cfile_cache_hit_bytes":4262390,"cfile_cache_miss":602,"cfile_cache_miss_bytes":24614714,"cfile_init":4,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":890,"lbm_read_time_us":12043,"lbm_reads_lt_1ms":618,"lbm_write_time_us":34493,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":642,"mutex_wait_us":309,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":9216,"update_count":3000}
I20260812 06:17:04.987195 11286 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:04.987650 11286 tablet_replica.cc:333] T 7b7270f61d5c43238a5f215a7239526c P 7f68ecacb430468aae5b179cbe57e4f4: stopping tablet replica
I20260812 06:17:04.989244 11286 raft_consensus.cc:2243] T 7b7270f61d5c43238a5f215a7239526c P 7f68ecacb430468aae5b179cbe57e4f4 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:04.989477 11286 raft_consensus.cc:2272] T 7b7270f61d5c43238a5f215a7239526c P 7f68ecacb430468aae5b179cbe57e4f4 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:04.994644 11286 tablet_server.cc:196] TabletServer@127.11.5.129:0 shutdown complete.
I20260812 06:17:05.037274 11286 master.cc:562] Master@127.11.5.190:33923 shutting down...
I20260812 06:17:05.043792 11286 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 38924f671be54f71b3b130c549c5d4bf [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:05.044023 11286 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 38924f671be54f71b3b130c549c5d4bf [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:05.044102 11286 tablet_replica.cc:333] T 00000000000000000000000000000000 P 38924f671be54f71b3b130c549c5d4bf: stopping tablet replica
I20260812 06:17:05.057011 11286 master.cc:584] Master@127.11.5.190:33923 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5766 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11397 ms total)

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