[==========] 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:18:08.429884 15253 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.14.229.126:35553
I20260812 06:18:08.430799 15253 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:18:08.431372 15253 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:08.437861 15259 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:18:08.438041 15253 server_base.cc:1061] running on GCE node
W20260812 06:18:08.438076 15258 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:18:08.438336 15261 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:18:08.438781 15253 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:08.438898 15253 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:18:08.438943 15253 hybrid_clock.cc:648] HybridClock initialized: now 1786515488438941 us; error 0 us; skew 500 ppm
I20260812 06:18:08.440609 15253 webserver.cc:533] Webserver started at http://127.14.229.126:37775/ using document root <none> and password file <none>
I20260812 06:18:08.441109 15253 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:08.441161 15253 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:08.441361 15253 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:08.442929 15253 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488419532-15253-0/minicluster-data/master-0-root/instance:
uuid: "a8e1902ecca3465083e084d36d16e855"
format_stamp: "Formatted at 2026-08-12 06:18:08 on dist-test-slave-f7th"
I20260812 06:18:08.446290 15253 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.005s	sys 0.000s
I20260812 06:18:08.448290 15266 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:18:08.449343 15253 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:08.449460 15253 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488419532-15253-0/minicluster-data/master-0-root
uuid: "a8e1902ecca3465083e084d36d16e855"
format_stamp: "Formatted at 2026-08-12 06:18:08 on dist-test-slave-f7th"
I20260812 06:18:08.449554 15253 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488419532-15253-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488419532-15253-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488419532-15253-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:18:08.459280 15253 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:08.459899 15253 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:18:08.460052 15253 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:08.468338 15253 rpc_server.cc:307] RPC server started. Bound to: 127.14.229.126:35553
I20260812 06:18:08.468350 15318 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.14.229.126:35553 every 8 connection(s)
I20260812 06:18:08.470640 15319 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:18:08.476146 15319 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a8e1902ecca3465083e084d36d16e855: Bootstrap starting.
I20260812 06:18:08.478605 15319 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P a8e1902ecca3465083e084d36d16e855: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:08.479557 15319 log.cc:826] T 00000000000000000000000000000000 P a8e1902ecca3465083e084d36d16e855: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:08.481340 15319 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a8e1902ecca3465083e084d36d16e855: No bootstrap required, opened a new log
I20260812 06:18:08.484231 15319 raft_consensus.cc:359] T 00000000000000000000000000000000 P a8e1902ecca3465083e084d36d16e855 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a8e1902ecca3465083e084d36d16e855" member_type: VOTER }
I20260812 06:18:08.484404 15319 raft_consensus.cc:385] T 00000000000000000000000000000000 P a8e1902ecca3465083e084d36d16e855 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:08.484474 15319 raft_consensus.cc:740] T 00000000000000000000000000000000 P a8e1902ecca3465083e084d36d16e855 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: a8e1902ecca3465083e084d36d16e855, State: Initialized, Role: FOLLOWER
I20260812 06:18:08.485096 15319 consensus_queue.cc:260] T 00000000000000000000000000000000 P a8e1902ecca3465083e084d36d16e855 [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: "a8e1902ecca3465083e084d36d16e855" member_type: VOTER }
I20260812 06:18:08.485251 15319 raft_consensus.cc:399] T 00000000000000000000000000000000 P a8e1902ecca3465083e084d36d16e855 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:08.485321 15319 raft_consensus.cc:493] T 00000000000000000000000000000000 P a8e1902ecca3465083e084d36d16e855 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:08.485443 15319 raft_consensus.cc:3060] T 00000000000000000000000000000000 P a8e1902ecca3465083e084d36d16e855 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:08.486236 15319 raft_consensus.cc:515] T 00000000000000000000000000000000 P a8e1902ecca3465083e084d36d16e855 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a8e1902ecca3465083e084d36d16e855" member_type: VOTER }
I20260812 06:18:08.486649 15319 leader_election.cc:304] T 00000000000000000000000000000000 P a8e1902ecca3465083e084d36d16e855 [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: a8e1902ecca3465083e084d36d16e855; no voters: 
I20260812 06:18:08.486984 15319 leader_election.cc:290] T 00000000000000000000000000000000 P a8e1902ecca3465083e084d36d16e855 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:08.487107 15322 raft_consensus.cc:2804] T 00000000000000000000000000000000 P a8e1902ecca3465083e084d36d16e855 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:08.487349 15322 raft_consensus.cc:697] T 00000000000000000000000000000000 P a8e1902ecca3465083e084d36d16e855 [term 1 LEADER]: Becoming Leader. State: Replica: a8e1902ecca3465083e084d36d16e855, State: Running, Role: LEADER
I20260812 06:18:08.487844 15322 consensus_queue.cc:237] T 00000000000000000000000000000000 P a8e1902ecca3465083e084d36d16e855 [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: "a8e1902ecca3465083e084d36d16e855" member_type: VOTER }
I20260812 06:18:08.488008 15319 sys_catalog.cc:565] T 00000000000000000000000000000000 P a8e1902ecca3465083e084d36d16e855 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:08.489917 15324 sys_catalog.cc:455] T 00000000000000000000000000000000 P a8e1902ecca3465083e084d36d16e855 [sys.catalog]: SysCatalogTable state changed. Reason: New leader a8e1902ecca3465083e084d36d16e855. Latest consensus state: current_term: 1 leader_uuid: "a8e1902ecca3465083e084d36d16e855" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a8e1902ecca3465083e084d36d16e855" member_type: VOTER } }
I20260812 06:18:08.490043 15324 sys_catalog.cc:458] T 00000000000000000000000000000000 P a8e1902ecca3465083e084d36d16e855 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:08.490290 15323 sys_catalog.cc:455] T 00000000000000000000000000000000 P a8e1902ecca3465083e084d36d16e855 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "a8e1902ecca3465083e084d36d16e855" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a8e1902ecca3465083e084d36d16e855" member_type: VOTER } }
I20260812 06:18:08.490374 15323 sys_catalog.cc:458] T 00000000000000000000000000000000 P a8e1902ecca3465083e084d36d16e855 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:08.490399 15336 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:08.490465 15253 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:08.492981 15336 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:08.498055 15336 catalog_manager.cc:1383] Generated new cluster ID: d1bf034da07c45248f614c7b7765b8be
I20260812 06:18:08.498123 15336 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:08.506994 15336 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:08.508112 15336 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:08.513948 15336 catalog_manager.cc:6092] T 00000000000000000000000000000000 P a8e1902ecca3465083e084d36d16e855: Generated new TSK 0
I20260812 06:18:08.514624 15336 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:08.523533 15253 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:08.526360 15342 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:18:08.526387 15344 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:18:08.526386 15341 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:18:08.526757 15253 server_base.cc:1061] running on GCE node
I20260812 06:18:08.526924 15253 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:08.526966 15253 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:18:08.526985 15253 hybrid_clock.cc:648] HybridClock initialized: now 1786515488526985 us; error 0 us; skew 500 ppm
I20260812 06:18:08.527889 15253 webserver.cc:533] Webserver started at http://127.14.229.65:32837/ using document root <none> and password file <none>
I20260812 06:18:08.528040 15253 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:08.528092 15253 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:08.528159 15253 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:08.528559 15253 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488419532-15253-0/minicluster-data/ts-0-root/instance:
uuid: "bb20501e840846cc89cc3312c7a2a2eb"
format_stamp: "Formatted at 2026-08-12 06:18:08 on dist-test-slave-f7th"
I20260812 06:18:08.530246 15253 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:08.531461 15349 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:18:08.531729 15253 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:08.531819 15253 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488419532-15253-0/minicluster-data/ts-0-root
uuid: "bb20501e840846cc89cc3312c7a2a2eb"
format_stamp: "Formatted at 2026-08-12 06:18:08 on dist-test-slave-f7th"
I20260812 06:18:08.531898 15253 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488419532-15253-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488419532-15253-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488419532-15253-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:18:08.541643 15253 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:08.542057 15253 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:08.542554 15253 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:08.543478 15253 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:08.543540 15253 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:08.543589 15253 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:08.543640 15253 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:08.549786 15253 rpc_server.cc:307] RPC server started. Bound to: 127.14.229.65:40231
I20260812 06:18:08.549829 15412 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.14.229.65:40231 every 8 connection(s)
I20260812 06:18:08.561336 15413 heartbeater.cc:344] Connected to a master server at 127.14.229.126:35553
I20260812 06:18:08.561614 15413 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:08.562117 15413 heartbeater.cc:507] Master 127.14.229.126:35553 requested a full tablet report, sending...
I20260812 06:18:08.563704 15283 ts_manager.cc:194] Registered new tserver with Master: bb20501e840846cc89cc3312c7a2a2eb (127.14.229.65:40231)
I20260812 06:18:08.563784 15253 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.013321796s
I20260812 06:18:08.565251 15283 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:33338
I20260812 06:18:08.574535 15283 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:33340:
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:18:08.590891 15377 tablet_service.cc:1511] Processing CreateTablet for tablet cdca0cf00e614418939d0e6cf72ddb98 (DEFAULT_TABLE table=heavy-update-compaction-test [id=2e96b8161d3e4b18a0a8c8f154db2cca]), partition=
I20260812 06:18:08.591375 15377 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet cdca0cf00e614418939d0e6cf72ddb98. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:08.594123 15425 tablet_bootstrap.cc:492] T cdca0cf00e614418939d0e6cf72ddb98 P bb20501e840846cc89cc3312c7a2a2eb: Bootstrap starting.
I20260812 06:18:08.595304 15425 tablet_bootstrap.cc:654] T cdca0cf00e614418939d0e6cf72ddb98 P bb20501e840846cc89cc3312c7a2a2eb: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:08.596608 15425 tablet_bootstrap.cc:492] T cdca0cf00e614418939d0e6cf72ddb98 P bb20501e840846cc89cc3312c7a2a2eb: No bootstrap required, opened a new log
I20260812 06:18:08.596774 15425 ts_tablet_manager.cc:1403] T cdca0cf00e614418939d0e6cf72ddb98 P bb20501e840846cc89cc3312c7a2a2eb: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:18:08.597333 15425 raft_consensus.cc:359] T cdca0cf00e614418939d0e6cf72ddb98 P bb20501e840846cc89cc3312c7a2a2eb [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bb20501e840846cc89cc3312c7a2a2eb" member_type: VOTER last_known_addr { host: "127.14.229.65" port: 40231 } }
I20260812 06:18:08.597456 15425 raft_consensus.cc:385] T cdca0cf00e614418939d0e6cf72ddb98 P bb20501e840846cc89cc3312c7a2a2eb [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:08.597489 15425 raft_consensus.cc:740] T cdca0cf00e614418939d0e6cf72ddb98 P bb20501e840846cc89cc3312c7a2a2eb [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: bb20501e840846cc89cc3312c7a2a2eb, State: Initialized, Role: FOLLOWER
I20260812 06:18:08.597667 15425 consensus_queue.cc:260] T cdca0cf00e614418939d0e6cf72ddb98 P bb20501e840846cc89cc3312c7a2a2eb [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: "bb20501e840846cc89cc3312c7a2a2eb" member_type: VOTER last_known_addr { host: "127.14.229.65" port: 40231 } }
I20260812 06:18:08.597769 15425 raft_consensus.cc:399] T cdca0cf00e614418939d0e6cf72ddb98 P bb20501e840846cc89cc3312c7a2a2eb [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:08.597843 15425 raft_consensus.cc:493] T cdca0cf00e614418939d0e6cf72ddb98 P bb20501e840846cc89cc3312c7a2a2eb [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:08.597899 15425 raft_consensus.cc:3060] T cdca0cf00e614418939d0e6cf72ddb98 P bb20501e840846cc89cc3312c7a2a2eb [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:08.598836 15425 raft_consensus.cc:515] T cdca0cf00e614418939d0e6cf72ddb98 P bb20501e840846cc89cc3312c7a2a2eb [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bb20501e840846cc89cc3312c7a2a2eb" member_type: VOTER last_known_addr { host: "127.14.229.65" port: 40231 } }
I20260812 06:18:08.598982 15425 leader_election.cc:304] T cdca0cf00e614418939d0e6cf72ddb98 P bb20501e840846cc89cc3312c7a2a2eb [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: bb20501e840846cc89cc3312c7a2a2eb; no voters: 
I20260812 06:18:08.599174 15425 leader_election.cc:290] T cdca0cf00e614418939d0e6cf72ddb98 P bb20501e840846cc89cc3312c7a2a2eb [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:08.599298 15427 raft_consensus.cc:2804] T cdca0cf00e614418939d0e6cf72ddb98 P bb20501e840846cc89cc3312c7a2a2eb [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:08.599522 15427 raft_consensus.cc:697] T cdca0cf00e614418939d0e6cf72ddb98 P bb20501e840846cc89cc3312c7a2a2eb [term 1 LEADER]: Becoming Leader. State: Replica: bb20501e840846cc89cc3312c7a2a2eb, State: Running, Role: LEADER
I20260812 06:18:08.599664 15425 ts_tablet_manager.cc:1434] T cdca0cf00e614418939d0e6cf72ddb98 P bb20501e840846cc89cc3312c7a2a2eb: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:08.599705 15427 consensus_queue.cc:237] T cdca0cf00e614418939d0e6cf72ddb98 P bb20501e840846cc89cc3312c7a2a2eb [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: "bb20501e840846cc89cc3312c7a2a2eb" member_type: VOTER last_known_addr { host: "127.14.229.65" port: 40231 } }
I20260812 06:18:08.600154 15413 heartbeater.cc:499] Master 127.14.229.126:35553 was elected leader, sending a full tablet report...
I20260812 06:18:08.602757 15283 catalog_manager.cc:5719] T cdca0cf00e614418939d0e6cf72ddb98 P bb20501e840846cc89cc3312c7a2a2eb reported cstate change: term changed from 0 to 1, leader changed from <none> to bb20501e840846cc89cc3312c7a2a2eb (127.14.229.65). New cstate: current_term: 1 leader_uuid: "bb20501e840846cc89cc3312c7a2a2eb" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bb20501e840846cc89cc3312c7a2a2eb" member_type: VOTER last_known_addr { host: "127.14.229.65" port: 40231 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:08.673542 15253 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.064s	user 0.017s	sys 0.013s
I20260812 06:18:08.801951 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling FlushMRSOp(cdca0cf00e614418939d0e6cf72ddb98): perf score=15.086190
I20260812 06:18:08.971057 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: FlushMRSOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.169s	user 0.102s	sys 0.049s Metrics: {"bytes_written":11897249,"cfile_init":1,"compiler_manager_pool.queue_time_us":768,"delete_count":0,"dirs.queue_time_us":62,"dirs.run_cpu_time_us":186,"dirs.run_wall_time_us":663,"drs_written":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4,"lbm_write_time_us":39938,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":656,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":106,"threads_started":1,"update_count":1450}
I20260812 06:18:08.972363 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling LogGCOp(cdca0cf00e614418939d0e6cf72ddb98): free 20743880 bytes of WAL
I20260812 06:18:08.973055 15354 log_reader.cc:385] T cdca0cf00e614418939d0e6cf72ddb98: removed 2 log segments from log reader
I20260812 06:18:08.973188 15354 log.cc:1079] T cdca0cf00e614418939d0e6cf72ddb98 P bb20501e840846cc89cc3312c7a2a2eb: Deleting log segment in path: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488419532-15253-0/minicluster-data/ts-0-root/wals/cdca0cf00e614418939d0e6cf72ddb98/wal-000000001 (ops 1-6)
I20260812 06:18:08.973284 15354 log.cc:1079] T cdca0cf00e614418939d0e6cf72ddb98 P bb20501e840846cc89cc3312c7a2a2eb: Deleting log segment in path: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488419532-15253-0/minicluster-data/ts-0-root/wals/cdca0cf00e614418939d0e6cf72ddb98/wal-000000002 (ops 7-11)
I20260812 06:18:08.977998 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: LogGCOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.005s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:18:08.978499 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling UndoDeltaBlockGCOp(cdca0cf00e614418939d0e6cf72ddb98): 12719216 bytes on disk
I20260812 06:18:08.979166 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: UndoDeltaBlockGCOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":77,"lbm_reads_lt_1ms":4}
I20260812 06:18:08.979655 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98): perf score=2.188937
I20260812 06:18:08.995920 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.016s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6038,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:08.996517 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling MajorDeltaCompactionOp(cdca0cf00e614418939d0e6cf72ddb98): perf score=1.000000
I20260812 06:18:09.139794 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: MajorDeltaCompactionOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.143s	user 0.112s	sys 0.029s Metrics: {"cfile_cache_miss":422,"cfile_cache_miss_bytes":20262036,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":541,"lbm_read_time_us":10153,"lbm_reads_lt_1ms":454,"lbm_write_time_us":26673,"lbm_writes_lt_1ms":433,"peak_mem_usage":49238594,"reinsert_count":0,"spinlock_wait_cycles":2688,"thread_start_us":345,"threads_started":5,"update_count":1950}
I20260812 06:18:09.140472 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98): perf score=10.126437
I20260812 06:18:09.190706 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.050s	user 0.025s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18704,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:09.191268 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98): perf score=2.188937
I20260812 06:18:09.208052 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.017s	user 0.011s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6228,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:09.208570 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling MajorDeltaCompactionOp(cdca0cf00e614418939d0e6cf72ddb98): perf score=1.000000
I20260812 06:18:09.347093 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: MajorDeltaCompactionOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.138s	user 0.100s	sys 0.033s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":557,"lbm_read_time_us":8504,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27680,"lbm_writes_lt_1ms":443,"mutex_wait_us":255,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":2000}
I20260812 06:18:09.347666 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98): perf score=10.126437
I20260812 06:18:09.397261 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.049s	user 0.026s	sys 0.012s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":17790,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:09.397753 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98): perf score=2.188937
I20260812 06:18:09.412707 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.015s	user 0.014s	sys 0.000s 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:18:09.413166 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling MajorDeltaCompactionOp(cdca0cf00e614418939d0e6cf72ddb98): perf score=1.000000
I20260812 06:18:09.555342 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: MajorDeltaCompactionOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.142s	user 0.095s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":377,"lbm_read_time_us":9827,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25868,"lbm_writes_lt_1ms":443,"mutex_wait_us":55,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:18:09.555859 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98): perf score=10.126437
I20260812 06:18:09.608335 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.052s	user 0.010s	sys 0.032s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15245,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:09.608934 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98): perf score=2.188937
I20260812 06:18:09.619653 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3966,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:09.620082 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling MajorDeltaCompactionOp(cdca0cf00e614418939d0e6cf72ddb98): perf score=1.000000
I20260812 06:18:09.783571 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: MajorDeltaCompactionOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.163s	user 0.120s	sys 0.037s 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":431,"lbm_read_time_us":10623,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26065,"lbm_writes_lt_1ms":443,"mutex_wait_us":279,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14464,"update_count":2000}
I20260812 06:18:09.784142 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98): perf score=10.126437
I20260812 06:18:09.830588 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.046s	user 0.016s	sys 0.019s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16216,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:09.831032 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98): perf score=2.188937
I20260812 06:18:09.845890 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5231,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:09.846379 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling MajorDeltaCompactionOp(cdca0cf00e614418939d0e6cf72ddb98): perf score=1.000000
I20260812 06:18:09.979662 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: MajorDeltaCompactionOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.133s	user 0.097s	sys 0.023s 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":810,"lbm_read_time_us":9470,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20544,"lbm_writes_lt_1ms":443,"mutex_wait_us":259,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:09.980192 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98): perf score=10.126437
I20260812 06:18:10.032428 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.052s	user 0.016s	sys 0.025s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18233,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:10.032963 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98): perf score=2.188937
I20260812 06:18:10.045849 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4761,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:10.046428 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling MajorDeltaCompactionOp(cdca0cf00e614418939d0e6cf72ddb98): perf score=1.000000
I20260812 06:18:10.176993 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: MajorDeltaCompactionOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.130s	user 0.098s	sys 0.032s 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":401,"lbm_read_time_us":8296,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25120,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:18:10.177614 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98): perf score=10.126437
I20260812 06:18:10.227910 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.050s	user 0.030s	sys 0.019s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":20178,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:10.228487 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98): perf score=2.188937
I20260812 06:18:10.256502 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.028s	user 0.006s	sys 0.010s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6588,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:10.256989 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98): perf score=2.188937
I20260812 06:18:10.270000 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.013s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5010,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:10.270501 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling FlushMRSOp(cdca0cf00e614418939d0e6cf72ddb98): perf score=1.000000
I20260812 06:18:10.305284 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: FlushMRSOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.035s	user 0.028s	sys 0.004s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":94,"dirs.run_cpu_time_us":219,"dirs.run_wall_time_us":2001,"drs_written":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1807,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:10.306414 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling LogGCOp(cdca0cf00e614418939d0e6cf72ddb98): free 112692371 bytes of WAL
I20260812 06:18:10.306736 15354 log_reader.cc:385] T cdca0cf00e614418939d0e6cf72ddb98: removed 11 log segments from log reader
I20260812 06:18:10.306843 15354 log.cc:1079] T cdca0cf00e614418939d0e6cf72ddb98 P bb20501e840846cc89cc3312c7a2a2eb: Deleting log segment in path: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488419532-15253-0/minicluster-data/ts-0-root/wals/cdca0cf00e614418939d0e6cf72ddb98/wal-000000003 (ops 12-16)
I20260812 06:18:10.306946 15354 log.cc:1079] T cdca0cf00e614418939d0e6cf72ddb98 P bb20501e840846cc89cc3312c7a2a2eb: Deleting log segment in path: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488419532-15253-0/minicluster-data/ts-0-root/wals/cdca0cf00e614418939d0e6cf72ddb98/wal-000000004 (ops 17-21)
I20260812 06:18:10.307030 15354 log.cc:1079] T cdca0cf00e614418939d0e6cf72ddb98 P bb20501e840846cc89cc3312c7a2a2eb: Deleting log segment in path: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488419532-15253-0/minicluster-data/ts-0-root/wals/cdca0cf00e614418939d0e6cf72ddb98/wal-000000005 (ops 22-26)
I20260812 06:18:10.307114 15354 log.cc:1079] T cdca0cf00e614418939d0e6cf72ddb98 P bb20501e840846cc89cc3312c7a2a2eb: Deleting log segment in path: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488419532-15253-0/minicluster-data/ts-0-root/wals/cdca0cf00e614418939d0e6cf72ddb98/wal-000000006 (ops 27-31)
I20260812 06:18:10.307207 15354 log.cc:1079] T cdca0cf00e614418939d0e6cf72ddb98 P bb20501e840846cc89cc3312c7a2a2eb: Deleting log segment in path: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488419532-15253-0/minicluster-data/ts-0-root/wals/cdca0cf00e614418939d0e6cf72ddb98/wal-000000007 (ops 32-36)
I20260812 06:18:10.307294 15354 log.cc:1079] T cdca0cf00e614418939d0e6cf72ddb98 P bb20501e840846cc89cc3312c7a2a2eb: Deleting log segment in path: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488419532-15253-0/minicluster-data/ts-0-root/wals/cdca0cf00e614418939d0e6cf72ddb98/wal-000000008 (ops 37-41)
I20260812 06:18:10.307374 15354 log.cc:1079] T cdca0cf00e614418939d0e6cf72ddb98 P bb20501e840846cc89cc3312c7a2a2eb: Deleting log segment in path: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488419532-15253-0/minicluster-data/ts-0-root/wals/cdca0cf00e614418939d0e6cf72ddb98/wal-000000009 (ops 42-46)
I20260812 06:18:10.307454 15354 log.cc:1079] T cdca0cf00e614418939d0e6cf72ddb98 P bb20501e840846cc89cc3312c7a2a2eb: Deleting log segment in path: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488419532-15253-0/minicluster-data/ts-0-root/wals/cdca0cf00e614418939d0e6cf72ddb98/wal-000000010 (ops 47-51)
I20260812 06:18:10.307533 15354 log.cc:1079] T cdca0cf00e614418939d0e6cf72ddb98 P bb20501e840846cc89cc3312c7a2a2eb: Deleting log segment in path: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488419532-15253-0/minicluster-data/ts-0-root/wals/cdca0cf00e614418939d0e6cf72ddb98/wal-000000011 (ops 52-56)
I20260812 06:18:10.307639 15354 log.cc:1079] T cdca0cf00e614418939d0e6cf72ddb98 P bb20501e840846cc89cc3312c7a2a2eb: Deleting log segment in path: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488419532-15253-0/minicluster-data/ts-0-root/wals/cdca0cf00e614418939d0e6cf72ddb98/wal-000000012 (ops 57-61)
I20260812 06:18:10.307742 15354 log.cc:1079] T cdca0cf00e614418939d0e6cf72ddb98 P bb20501e840846cc89cc3312c7a2a2eb: Deleting log segment in path: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488419532-15253-0/minicluster-data/ts-0-root/wals/cdca0cf00e614418939d0e6cf72ddb98/wal-000000013 (ops 62-66)
I20260812 06:18:10.332100 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: LogGCOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.025s	user 0.003s	sys 0.021s Metrics: {}
I20260812 06:18:10.332624 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling UndoDeltaBlockGCOp(cdca0cf00e614418939d0e6cf72ddb98): 447 bytes on disk
I20260812 06:18:10.333246 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: UndoDeltaBlockGCOp(cdca0cf00e614418939d0e6cf72ddb98) 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:18:10.333753 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98): perf score=3.181125
I20260812 06:18:10.362857 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.029s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":5621,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:10.363358 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98): perf score=2.188937
I20260812 06:18:10.375363 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4361,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:10.375883 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling MajorDeltaCompactionOp(cdca0cf00e614418939d0e6cf72ddb98): perf score=1.000000
I20260812 06:18:10.610942 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: MajorDeltaCompactionOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.235s	user 0.170s	sys 0.055s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979860,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":470,"lbm_read_time_us":15453,"lbm_reads_lt_1ms":775,"lbm_write_time_us":41162,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":2048,"thread_start_us":80,"threads_started":1,"update_count":3500}
I20260812 06:18:10.612375 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98): perf score=18.063937
I20260812 06:18:10.667076 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.054s	user 0.037s	sys 0.013s Metrics: {"bytes_written":20512318,"delete_count":0,"lbm_write_time_us":24085,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:10.667546 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98): perf score=2.188937
I20260812 06:18:10.683796 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.016s	user 0.013s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5371,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:10.684352 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling MajorDeltaCompactionOp(cdca0cf00e614418939d0e6cf72ddb98): perf score=1.000000
I20260812 06:18:10.854903 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: MajorDeltaCompactionOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.170s	user 0.120s	sys 0.045s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877105,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":775,"lbm_read_time_us":12507,"lbm_reads_lt_1ms":664,"lbm_write_time_us":34126,"lbm_writes_lt_1ms":643,"mutex_wait_us":1,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":3000}
I20260812 06:18:10.855897 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98): perf score=14.095187
I20260812 06:18:10.902391 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.044s	user 0.023s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19186,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:10.902966 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98): perf score=2.188937
I20260812 06:18:10.916299 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.013s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4816,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:10.916898 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling MajorDeltaCompactionOp(cdca0cf00e614418939d0e6cf72ddb98): perf score=1.000000
I20260812 06:18:11.088069 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: MajorDeltaCompactionOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.171s	user 0.138s	sys 0.025s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":97,"lbm_read_time_us":8490,"lbm_reads_lt_1ms":564,"lbm_write_time_us":36174,"lbm_writes_lt_1ms":543,"mutex_wait_us":43,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8320,"update_count":2500}
I20260812 06:18:11.088678 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98): perf score=15.087375
I20260812 06:18:11.133358 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.044s	user 0.031s	sys 0.012s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":19531,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:18:11.133880 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98): perf score=2.188937
I20260812 06:18:11.146374 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.012s	user 0.000s	sys 0.011s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4854,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:11.146916 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling MajorDeltaCompactionOp(cdca0cf00e614418939d0e6cf72ddb98): perf score=1.000000
I20260812 06:18:11.351999 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: MajorDeltaCompactionOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.205s	user 0.100s	sys 0.095s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774675,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":166,"lbm_read_time_us":14215,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33793,"lbm_writes_lt_1ms":543,"mutex_wait_us":78,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:11.352627 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98): perf score=14.095187
I20260812 06:18:11.418915 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.066s	user 0.035s	sys 0.009s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21075,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:11.419463 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98): perf score=2.188937
I20260812 06:18:11.435461 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.016s	user 0.005s	sys 0.009s Metrics: {"bytes_written":4102660,"delete_count":0,"lbm_write_time_us":6155,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:11.435993 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling MajorDeltaCompactionOp(cdca0cf00e614418939d0e6cf72ddb98): perf score=1.000000
I20260812 06:18:11.621739 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: MajorDeltaCompactionOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.186s	user 0.128s	sys 0.053s 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":319,"lbm_read_time_us":13948,"lbm_reads_lt_1ms":572,"lbm_write_time_us":35166,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4096,"update_count":2500}
I20260812 06:18:11.622582 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98): perf score=11.118625
I20260812 06:18:11.667493 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.045s	user 0.018s	sys 0.023s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15119,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:11.668049 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98): perf score=2.188937
I20260812 06:18:11.677138 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.009s	user 0.006s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3202,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:11.677532 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling MajorDeltaCompactionOp(cdca0cf00e614418939d0e6cf72ddb98): perf score=1.000000
I20260812 06:18:11.841229 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: MajorDeltaCompactionOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.164s	user 0.087s	sys 0.073s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":114,"lbm_read_time_us":9730,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28740,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":61,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:11.841830 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98): perf score=10.126437
I20260812 06:18:11.893759 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.052s	user 0.013s	sys 0.017s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13950,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:11.894357 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98): perf score=2.188937
I20260812 06:18:11.906725 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5124,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":102,"reinsert_count":0,"update_count":500}
I20260812 06:18:11.907917 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling FlushMRSOp(cdca0cf00e614418939d0e6cf72ddb98): perf score=1.000000
I20260812 06:18:11.939370 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: FlushMRSOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.031s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":47,"dirs.run_cpu_time_us":162,"dirs.run_wall_time_us":1687,"drs_written":1,"lbm_read_time_us":46,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1539,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:11.940315 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling LogGCOp(cdca0cf00e614418939d0e6cf72ddb98): free 127961107 bytes of WAL
I20260812 06:18:11.940616 15354 log_reader.cc:385] T cdca0cf00e614418939d0e6cf72ddb98: removed 12 log segments from log reader
I20260812 06:18:11.940670 15354 log.cc:1079] T cdca0cf00e614418939d0e6cf72ddb98 P bb20501e840846cc89cc3312c7a2a2eb: Deleting log segment in path: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488419532-15253-0/minicluster-data/ts-0-root/wals/cdca0cf00e614418939d0e6cf72ddb98/wal-000000014 (ops 67-71)
I20260812 06:18:11.940753 15354 log.cc:1079] T cdca0cf00e614418939d0e6cf72ddb98 P bb20501e840846cc89cc3312c7a2a2eb: Deleting log segment in path: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488419532-15253-0/minicluster-data/ts-0-root/wals/cdca0cf00e614418939d0e6cf72ddb98/wal-000000015 (ops 72-76)
I20260812 06:18:11.940790 15354 log.cc:1079] T cdca0cf00e614418939d0e6cf72ddb98 P bb20501e840846cc89cc3312c7a2a2eb: Deleting log segment in path: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488419532-15253-0/minicluster-data/ts-0-root/wals/cdca0cf00e614418939d0e6cf72ddb98/wal-000000016 (ops 77-81)
I20260812 06:18:11.940815 15354 log.cc:1079] T cdca0cf00e614418939d0e6cf72ddb98 P bb20501e840846cc89cc3312c7a2a2eb: Deleting log segment in path: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488419532-15253-0/minicluster-data/ts-0-root/wals/cdca0cf00e614418939d0e6cf72ddb98/wal-000000017 (ops 82-86)
I20260812 06:18:11.940846 15354 log.cc:1079] T cdca0cf00e614418939d0e6cf72ddb98 P bb20501e840846cc89cc3312c7a2a2eb: Deleting log segment in path: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488419532-15253-0/minicluster-data/ts-0-root/wals/cdca0cf00e614418939d0e6cf72ddb98/wal-000000018 (ops 87-91)
I20260812 06:18:11.940877 15354 log.cc:1079] T cdca0cf00e614418939d0e6cf72ddb98 P bb20501e840846cc89cc3312c7a2a2eb: Deleting log segment in path: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488419532-15253-0/minicluster-data/ts-0-root/wals/cdca0cf00e614418939d0e6cf72ddb98/wal-000000019 (ops 92-96)
I20260812 06:18:11.940907 15354 log.cc:1079] T cdca0cf00e614418939d0e6cf72ddb98 P bb20501e840846cc89cc3312c7a2a2eb: Deleting log segment in path: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488419532-15253-0/minicluster-data/ts-0-root/wals/cdca0cf00e614418939d0e6cf72ddb98/wal-000000020 (ops 97-101)
I20260812 06:18:11.940937 15354 log.cc:1079] T cdca0cf00e614418939d0e6cf72ddb98 P bb20501e840846cc89cc3312c7a2a2eb: Deleting log segment in path: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488419532-15253-0/minicluster-data/ts-0-root/wals/cdca0cf00e614418939d0e6cf72ddb98/wal-000000021 (ops 102-106)
I20260812 06:18:11.940968 15354 log.cc:1079] T cdca0cf00e614418939d0e6cf72ddb98 P bb20501e840846cc89cc3312c7a2a2eb: Deleting log segment in path: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488419532-15253-0/minicluster-data/ts-0-root/wals/cdca0cf00e614418939d0e6cf72ddb98/wal-000000022 (ops 107-111)
I20260812 06:18:11.940996 15354 log.cc:1079] T cdca0cf00e614418939d0e6cf72ddb98 P bb20501e840846cc89cc3312c7a2a2eb: Deleting log segment in path: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488419532-15253-0/minicluster-data/ts-0-root/wals/cdca0cf00e614418939d0e6cf72ddb98/wal-000000023 (ops 112-116)
I20260812 06:18:11.941025 15354 log.cc:1079] T cdca0cf00e614418939d0e6cf72ddb98 P bb20501e840846cc89cc3312c7a2a2eb: Deleting log segment in path: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488419532-15253-0/minicluster-data/ts-0-root/wals/cdca0cf00e614418939d0e6cf72ddb98/wal-000000024 (ops 117-121)
I20260812 06:18:11.941054 15354 log.cc:1079] T cdca0cf00e614418939d0e6cf72ddb98 P bb20501e840846cc89cc3312c7a2a2eb: Deleting log segment in path: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488419532-15253-0/minicluster-data/ts-0-root/wals/cdca0cf00e614418939d0e6cf72ddb98/wal-000000025 (ops 122-126)
I20260812 06:18:11.966874 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: LogGCOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.026s	user 0.003s	sys 0.022s Metrics: {}
I20260812 06:18:11.967402 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling UndoDeltaBlockGCOp(cdca0cf00e614418939d0e6cf72ddb98): 483 bytes on disk
I20260812 06:18:11.968319 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: UndoDeltaBlockGCOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":507,"lbm_reads_lt_1ms":4}
I20260812 06:18:11.968894 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98): perf score=3.181125
I20260812 06:18:11.993360 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.024s	user 0.015s	sys 0.006s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":7777,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:11.993834 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98): perf score=2.188937
I20260812 06:18:12.005517 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4954,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":92,"reinsert_count":0,"update_count":450}
I20260812 06:18:12.006016 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling MajorDeltaCompactionOp(cdca0cf00e614418939d0e6cf72ddb98): perf score=1.000000
I20260812 06:18:12.227936 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: MajorDeltaCompactionOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.222s	user 0.139s	sys 0.064s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877326,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":193,"lbm_read_time_us":15318,"lbm_reads_1-10_ms":1,"lbm_reads_lt_1ms":673,"lbm_write_time_us":32299,"lbm_writes_lt_1ms":643,"mutex_wait_us":23,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":30592,"thread_start_us":60,"threads_started":1,"update_count":3000}
I20260812 06:18:12.228492 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98): perf score=14.095187
I20260812 06:18:12.297170 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.069s	user 0.034s	sys 0.019s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18733,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:12.297883 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98): perf score=2.188937
I20260812 06:18:12.313369 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5868,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:12.313962 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling MajorDeltaCompactionOp(cdca0cf00e614418939d0e6cf72ddb98): perf score=1.000000
I20260812 06:18:12.487485 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: MajorDeltaCompactionOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.173s	user 0.139s	sys 0.032s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":2216,"lbm_read_time_us":13717,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28678,"lbm_writes_lt_1ms":543,"mutex_wait_us":1658,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:12.488111 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98): perf score=11.118625
I20260812 06:18:12.529752 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.041s	user 0.038s	sys 0.000s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":17737,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:12.530332 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98): perf score=2.188937
I20260812 06:18:12.546056 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.016s	user 0.011s	sys 0.002s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5964,"lbm_writes_lt_1ms":93,"reinsert_count":0,"spinlock_wait_cycles":522240,"update_count":450}
I20260812 06:18:12.546613 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling MajorDeltaCompactionOp(cdca0cf00e614418939d0e6cf72ddb98): perf score=1.000000
I20260812 06:18:12.685793 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: MajorDeltaCompactionOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.139s	user 0.100s	sys 0.038s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672269,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":839,"lbm_read_time_us":9528,"lbm_reads_lt_1ms":468,"lbm_write_time_us":24517,"lbm_writes_lt_1ms":443,"mutex_wait_us":265,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12800,"update_count":2000}
I20260812 06:18:12.686395 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98): perf score=10.126437
I20260812 06:18:12.728916 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.042s	user 0.021s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14942,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:12.729385 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98): perf score=2.188937
I20260812 06:18:12.744956 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.015s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5424,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:12.745527 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling MajorDeltaCompactionOp(cdca0cf00e614418939d0e6cf72ddb98): perf score=1.000000
I20260812 06:18:12.883558 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: MajorDeltaCompactionOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.138s	user 0.105s	sys 0.032s 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":118,"lbm_read_time_us":7886,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25426,"lbm_writes_lt_1ms":443,"mutex_wait_us":43,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:18:12.884179 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98): perf score=10.126437
I20260812 06:18:12.927008 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.042s	user 0.027s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16039,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:12.927628 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98): perf score=2.188937
I20260812 06:18:12.945178 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.017s	user 0.007s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6774,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:12.945752 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling MajorDeltaCompactionOp(cdca0cf00e614418939d0e6cf72ddb98): perf score=1.000000
I20260812 06:18:13.091529 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: MajorDeltaCompactionOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.146s	user 0.125s	sys 0.020s 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":131,"lbm_read_time_us":8843,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29003,"lbm_writes_lt_1ms":443,"mutex_wait_us":34,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:13.092146 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98): perf score=10.126437
I20260812 06:18:13.132264 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.040s	user 0.024s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13861,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:13.132812 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98): perf score=2.188937
I20260812 06:18:13.142833 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3736,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:13.143239 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling MajorDeltaCompactionOp(cdca0cf00e614418939d0e6cf72ddb98): perf score=1.000000
I20260812 06:18:13.303242 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: MajorDeltaCompactionOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.160s	user 0.077s	sys 0.080s 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":999,"lbm_read_time_us":10117,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26628,"lbm_writes_lt_1ms":443,"mutex_wait_us":450,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12672,"update_count":2000}
I20260812 06:18:13.303900 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98): perf score=10.126437
I20260812 06:18:13.347635 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.043s	user 0.024s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18841,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:13.348281 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98): perf score=2.188937
I20260812 06:18:13.364315 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.016s	user 0.006s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6017,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:13.364897 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling MajorDeltaCompactionOp(cdca0cf00e614418939d0e6cf72ddb98): perf score=1.000000
I20260812 06:18:13.487850 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: MajorDeltaCompactionOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.123s	user 0.107s	sys 0.015s 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":124,"lbm_read_time_us":7968,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22214,"lbm_writes_lt_1ms":443,"mutex_wait_us":40,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9088,"update_count":2000}
I20260812 06:18:13.488526 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98): perf score=10.126437
I20260812 06:18:13.537876 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.049s	user 0.013s	sys 0.020s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15295,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:13.538527 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98): perf score=2.188937
I20260812 06:18:13.557719 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.019s	user 0.009s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6941,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:13.558336 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling FlushMRSOp(cdca0cf00e614418939d0e6cf72ddb98): perf score=1.000000
I20260812 06:18:13.599758 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: FlushMRSOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.041s	user 0.035s	sys 0.004s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":67,"dirs.run_cpu_time_us":224,"dirs.run_wall_time_us":1321,"drs_written":1,"lbm_read_time_us":103,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2230,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32,"spinlock_wait_cycles":17792}
I20260812 06:18:13.600963 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling LogGCOp(cdca0cf00e614418939d0e6cf72ddb98): free 133477692 bytes of WAL
I20260812 06:18:13.601284 15354 log_reader.cc:385] T cdca0cf00e614418939d0e6cf72ddb98: removed 13 log segments from log reader
I20260812 06:18:13.601356 15354 log.cc:1079] T cdca0cf00e614418939d0e6cf72ddb98 P bb20501e840846cc89cc3312c7a2a2eb: Deleting log segment in path: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488419532-15253-0/minicluster-data/ts-0-root/wals/cdca0cf00e614418939d0e6cf72ddb98/wal-000000026 (ops 127-131)
I20260812 06:18:13.601466 15354 log.cc:1079] T cdca0cf00e614418939d0e6cf72ddb98 P bb20501e840846cc89cc3312c7a2a2eb: Deleting log segment in path: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488419532-15253-0/minicluster-data/ts-0-root/wals/cdca0cf00e614418939d0e6cf72ddb98/wal-000000027 (ops 132-136)
I20260812 06:18:13.601548 15354 log.cc:1079] T cdca0cf00e614418939d0e6cf72ddb98 P bb20501e840846cc89cc3312c7a2a2eb: Deleting log segment in path: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488419532-15253-0/minicluster-data/ts-0-root/wals/cdca0cf00e614418939d0e6cf72ddb98/wal-000000028 (ops 137-141)
I20260812 06:18:13.601605 15354 log.cc:1079] T cdca0cf00e614418939d0e6cf72ddb98 P bb20501e840846cc89cc3312c7a2a2eb: Deleting log segment in path: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488419532-15253-0/minicluster-data/ts-0-root/wals/cdca0cf00e614418939d0e6cf72ddb98/wal-000000029 (ops 142-146)
I20260812 06:18:13.601665 15354 log.cc:1079] T cdca0cf00e614418939d0e6cf72ddb98 P bb20501e840846cc89cc3312c7a2a2eb: Deleting log segment in path: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488419532-15253-0/minicluster-data/ts-0-root/wals/cdca0cf00e614418939d0e6cf72ddb98/wal-000000030 (ops 147-151)
I20260812 06:18:13.601788 15354 log.cc:1079] T cdca0cf00e614418939d0e6cf72ddb98 P bb20501e840846cc89cc3312c7a2a2eb: Deleting log segment in path: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488419532-15253-0/minicluster-data/ts-0-root/wals/cdca0cf00e614418939d0e6cf72ddb98/wal-000000031 (ops 152-156)
I20260812 06:18:13.601871 15354 log.cc:1079] T cdca0cf00e614418939d0e6cf72ddb98 P bb20501e840846cc89cc3312c7a2a2eb: Deleting log segment in path: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488419532-15253-0/minicluster-data/ts-0-root/wals/cdca0cf00e614418939d0e6cf72ddb98/wal-000000032 (ops 157-161)
I20260812 06:18:13.601933 15354 log.cc:1079] T cdca0cf00e614418939d0e6cf72ddb98 P bb20501e840846cc89cc3312c7a2a2eb: Deleting log segment in path: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488419532-15253-0/minicluster-data/ts-0-root/wals/cdca0cf00e614418939d0e6cf72ddb98/wal-000000033 (ops 162-166)
I20260812 06:18:13.601992 15354 log.cc:1079] T cdca0cf00e614418939d0e6cf72ddb98 P bb20501e840846cc89cc3312c7a2a2eb: Deleting log segment in path: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488419532-15253-0/minicluster-data/ts-0-root/wals/cdca0cf00e614418939d0e6cf72ddb98/wal-000000034 (ops 167-171)
I20260812 06:18:13.602049 15354 log.cc:1079] T cdca0cf00e614418939d0e6cf72ddb98 P bb20501e840846cc89cc3312c7a2a2eb: Deleting log segment in path: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488419532-15253-0/minicluster-data/ts-0-root/wals/cdca0cf00e614418939d0e6cf72ddb98/wal-000000035 (ops 172-176)
I20260812 06:18:13.602119 15354 log.cc:1079] T cdca0cf00e614418939d0e6cf72ddb98 P bb20501e840846cc89cc3312c7a2a2eb: Deleting log segment in path: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488419532-15253-0/minicluster-data/ts-0-root/wals/cdca0cf00e614418939d0e6cf72ddb98/wal-000000036 (ops 177-181)
I20260812 06:18:13.602173 15354 log.cc:1079] T cdca0cf00e614418939d0e6cf72ddb98 P bb20501e840846cc89cc3312c7a2a2eb: Deleting log segment in path: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488419532-15253-0/minicluster-data/ts-0-root/wals/cdca0cf00e614418939d0e6cf72ddb98/wal-000000037 (ops 182-186)
I20260812 06:18:13.602218 15354 log.cc:1079] T cdca0cf00e614418939d0e6cf72ddb98 P bb20501e840846cc89cc3312c7a2a2eb: Deleting log segment in path: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488419532-15253-0/minicluster-data/ts-0-root/wals/cdca0cf00e614418939d0e6cf72ddb98/wal-000000038 (ops 187-191)
I20260812 06:18:13.626160 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: LogGCOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.025s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:18:13.626607 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98): perf score=4.173312
I20260812 06:18:13.646054 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.019s	user 0.004s	sys 0.012s Metrics: {"bytes_written":6030801,"delete_count":0,"lbm_write_time_us":7726,"lbm_writes_lt_1ms":150,"reinsert_count":0,"update_count":735}
I20260812 06:18:13.646592 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling UndoDeltaBlockGCOp(cdca0cf00e614418939d0e6cf72ddb98): 492 bytes on disk
I20260812 06:18:13.647076 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: UndoDeltaBlockGCOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":79,"lbm_reads_lt_1ms":4}
I20260812 06:18:13.647879 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98): perf score=1.196750
I20260812 06:18:13.658963 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":2174479,"delete_count":0,"lbm_write_time_us":3901,"lbm_writes_lt_1ms":56,"reinsert_count":0,"update_count":265}
I20260812 06:18:13.659428 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling MajorDeltaCompactionOp(cdca0cf00e614418939d0e6cf72ddb98): perf score=1.000000
I20260812 06:18:13.821727 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: MajorDeltaCompactionOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.162s	user 0.114s	sys 0.043s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877294,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1698,"dirs.run_cpu_time_us":832,"dirs.run_wall_time_us":8038,"lbm_read_time_us":12651,"lbm_reads_lt_1ms":674,"lbm_write_time_us":30122,"lbm_writes_lt_1ms":643,"mutex_wait_us":862,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":15360,"update_count":3000}
I20260812 06:18:13.822368 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98): perf score=11.118625
I20260812 06:18:13.853781 15253 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.180s	user 1.828s	sys 0.136s
I20260812 06:18:13.856096 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.033s	user 0.023s	sys 0.008s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":12882,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:13.856716 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98): perf score=2.188937
I20260812 06:18:13.868377 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: FlushDeltaMemStoresOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.011s	user 0.009s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4527,"lbm_writes_lt_1ms":93,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":450}
I20260812 06:18:13.868959 15414 maintenance_manager.cc:419] P bb20501e840846cc89cc3312c7a2a2eb: Scheduling MajorDeltaCompactionOp(cdca0cf00e614418939d0e6cf72ddb98): perf score=1.000000
I20260812 06:18:13.894654 15253 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.040s	user 0.002s	sys 0.000s
I20260812 06:18:13.895231 15253 tablet_server.cc:179] TabletServer@127.14.229.65:0 shutting down...
I20260812 06:18:13.984850 15354 maintenance_manager.cc:643] P bb20501e840846cc89cc3312c7a2a2eb: MajorDeltaCompactionOp(cdca0cf00e614418939d0e6cf72ddb98) complete. Timing: real 0.116s	user 0.075s	sys 0.040s Metrics: {"cfile_cache_hit":311,"cfile_cache_hit_bytes":12717601,"cfile_cache_miss":121,"cfile_cache_miss_bytes":7954667,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":211,"lbm_read_time_us":4687,"lbm_reads_lt_1ms":153,"lbm_write_time_us":24836,"lbm_writes_lt_1ms":443,"mutex_wait_us":34,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8576,"update_count":2000}
I20260812 06:18:13.985502 15253 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:13.985884 15253 tablet_replica.cc:333] T cdca0cf00e614418939d0e6cf72ddb98 P bb20501e840846cc89cc3312c7a2a2eb: stopping tablet replica
I20260812 06:18:13.986104 15253 raft_consensus.cc:2243] T cdca0cf00e614418939d0e6cf72ddb98 P bb20501e840846cc89cc3312c7a2a2eb [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:13.986340 15253 raft_consensus.cc:2272] T cdca0cf00e614418939d0e6cf72ddb98 P bb20501e840846cc89cc3312c7a2a2eb [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:13.991629 15253 tablet_server.cc:196] TabletServer@127.14.229.65:0 shutdown complete.
I20260812 06:18:14.023487 15253 master.cc:562] Master@127.14.229.126:35553 shutting down...
I20260812 06:18:14.026880 15253 raft_consensus.cc:2243] T 00000000000000000000000000000000 P a8e1902ecca3465083e084d36d16e855 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:14.027048 15253 raft_consensus.cc:2272] T 00000000000000000000000000000000 P a8e1902ecca3465083e084d36d16e855 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:14.027119 15253 tablet_replica.cc:333] T 00000000000000000000000000000000 P a8e1902ecca3465083e084d36d16e855: stopping tablet replica
I20260812 06:18:14.039279 15253 master.cc:584] Master@127.14.229.126:35553 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5677 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:14.117169 15253 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.14.229.126:43557
I20260812 06:18:14.117548 15253 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:14.119498 15445 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:18:14.119529 15448 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:18:14.119591 15253 server_base.cc:1061] running on GCE node
W20260812 06:18:14.119735 15446 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:18:14.120028 15253 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:14.120070 15253 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:18:14.120090 15253 hybrid_clock.cc:648] HybridClock initialized: now 1786515494120090 us; error 0 us; skew 500 ppm
I20260812 06:18:14.120886 15253 webserver.cc:533] Webserver started at http://127.14.229.126:42541/ using document root <none> and password file <none>
I20260812 06:18:14.121035 15253 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:14.121083 15253 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:14.121165 15253 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:14.121548 15253 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488419532-15253-0/minicluster-data/master-0-root/instance:
uuid: "af83a4a283ed456aa15485a074e13fca"
format_stamp: "Formatted at 2026-08-12 06:18:14 on dist-test-slave-f7th"
I20260812 06:18:14.123059 15253 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:14.126152 15453 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:18:14.126405 15253 fs_manager.cc:730] Time spent opening block manager: real 0.003s	user 0.001s	sys 0.000s
I20260812 06:18:14.126480 15253 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488419532-15253-0/minicluster-data/master-0-root
uuid: "af83a4a283ed456aa15485a074e13fca"
format_stamp: "Formatted at 2026-08-12 06:18:14 on dist-test-slave-f7th"
I20260812 06:18:14.126560 15253 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488419532-15253-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488419532-15253-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488419532-15253-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:18:14.136301 15253 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:14.136719 15253 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:14.141379 15253 rpc_server.cc:307] RPC server started. Bound to: 127.14.229.126:43557
I20260812 06:18:14.144213 15505 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.14.229.126:43557 every 8 connection(s)
I20260812 06:18:14.144779 15506 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:18:14.146781 15506 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P af83a4a283ed456aa15485a074e13fca: Bootstrap starting.
I20260812 06:18:14.147550 15506 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P af83a4a283ed456aa15485a074e13fca: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:14.148672 15506 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P af83a4a283ed456aa15485a074e13fca: No bootstrap required, opened a new log
I20260812 06:18:14.149041 15506 raft_consensus.cc:359] T 00000000000000000000000000000000 P af83a4a283ed456aa15485a074e13fca [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "af83a4a283ed456aa15485a074e13fca" member_type: VOTER }
I20260812 06:18:14.149124 15506 raft_consensus.cc:385] T 00000000000000000000000000000000 P af83a4a283ed456aa15485a074e13fca [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:14.149154 15506 raft_consensus.cc:740] T 00000000000000000000000000000000 P af83a4a283ed456aa15485a074e13fca [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: af83a4a283ed456aa15485a074e13fca, State: Initialized, Role: FOLLOWER
I20260812 06:18:14.149287 15506 consensus_queue.cc:260] T 00000000000000000000000000000000 P af83a4a283ed456aa15485a074e13fca [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: "af83a4a283ed456aa15485a074e13fca" member_type: VOTER }
I20260812 06:18:14.149370 15506 raft_consensus.cc:399] T 00000000000000000000000000000000 P af83a4a283ed456aa15485a074e13fca [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:14.149408 15506 raft_consensus.cc:493] T 00000000000000000000000000000000 P af83a4a283ed456aa15485a074e13fca [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:14.149456 15506 raft_consensus.cc:3060] T 00000000000000000000000000000000 P af83a4a283ed456aa15485a074e13fca [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:14.150094 15506 raft_consensus.cc:515] T 00000000000000000000000000000000 P af83a4a283ed456aa15485a074e13fca [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "af83a4a283ed456aa15485a074e13fca" member_type: VOTER }
I20260812 06:18:14.150216 15506 leader_election.cc:304] T 00000000000000000000000000000000 P af83a4a283ed456aa15485a074e13fca [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: af83a4a283ed456aa15485a074e13fca; no voters: 
I20260812 06:18:14.150381 15506 leader_election.cc:290] T 00000000000000000000000000000000 P af83a4a283ed456aa15485a074e13fca [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:14.150512 15509 raft_consensus.cc:2804] T 00000000000000000000000000000000 P af83a4a283ed456aa15485a074e13fca [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:14.150774 15509 raft_consensus.cc:697] T 00000000000000000000000000000000 P af83a4a283ed456aa15485a074e13fca [term 1 LEADER]: Becoming Leader. State: Replica: af83a4a283ed456aa15485a074e13fca, State: Running, Role: LEADER
I20260812 06:18:14.150815 15506 sys_catalog.cc:565] T 00000000000000000000000000000000 P af83a4a283ed456aa15485a074e13fca [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:14.150974 15509 consensus_queue.cc:237] T 00000000000000000000000000000000 P af83a4a283ed456aa15485a074e13fca [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: "af83a4a283ed456aa15485a074e13fca" member_type: VOTER }
I20260812 06:18:14.151422 15510 sys_catalog.cc:455] T 00000000000000000000000000000000 P af83a4a283ed456aa15485a074e13fca [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "af83a4a283ed456aa15485a074e13fca" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "af83a4a283ed456aa15485a074e13fca" member_type: VOTER } }
I20260812 06:18:14.151451 15511 sys_catalog.cc:455] T 00000000000000000000000000000000 P af83a4a283ed456aa15485a074e13fca [sys.catalog]: SysCatalogTable state changed. Reason: New leader af83a4a283ed456aa15485a074e13fca. Latest consensus state: current_term: 1 leader_uuid: "af83a4a283ed456aa15485a074e13fca" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "af83a4a283ed456aa15485a074e13fca" member_type: VOTER } }
I20260812 06:18:14.151556 15511 sys_catalog.cc:458] T 00000000000000000000000000000000 P af83a4a283ed456aa15485a074e13fca [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:14.151510 15510 sys_catalog.cc:458] T 00000000000000000000000000000000 P af83a4a283ed456aa15485a074e13fca [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:14.152694 15253 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:18:14.153282 15525 catalog_manager.cc:1594] T 00000000000000000000000000000000 P af83a4a283ed456aa15485a074e13fca: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:18:14.153357 15525 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:18:14.153445 15517 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:14.154119 15517 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:14.155963 15517 catalog_manager.cc:1383] Generated new cluster ID: 65d73984f5f94ef6bac267fa03e25170
I20260812 06:18:14.156064 15517 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:14.172645 15517 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:14.173208 15517 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:14.185539 15517 catalog_manager.cc:6092] T 00000000000000000000000000000000 P af83a4a283ed456aa15485a074e13fca: Generated new TSK 0
I20260812 06:18:14.185752 15517 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:14.217254 15253 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:14.219269 15527 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:18:14.219372 15530 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:18:14.219290 15528 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:18:14.219527 15253 server_base.cc:1061] running on GCE node
I20260812 06:18:14.219848 15253 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:14.219906 15253 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:18:14.219928 15253 hybrid_clock.cc:648] HybridClock initialized: now 1786515494219928 us; error 0 us; skew 500 ppm
I20260812 06:18:14.220799 15253 webserver.cc:533] Webserver started at http://127.14.229.65:42185/ using document root <none> and password file <none>
I20260812 06:18:14.220957 15253 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:14.221004 15253 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:14.221076 15253 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:14.221473 15253 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488419532-15253-0/minicluster-data/ts-0-root/instance:
uuid: "886118d1fe504c44bdc65ed04e4dc724"
format_stamp: "Formatted at 2026-08-12 06:18:14 on dist-test-slave-f7th"
I20260812 06:18:14.222847 15253 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:18:14.223735 15535 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:18:14.223980 15253 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:14.224045 15253 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488419532-15253-0/minicluster-data/ts-0-root
uuid: "886118d1fe504c44bdc65ed04e4dc724"
format_stamp: "Formatted at 2026-08-12 06:18:14 on dist-test-slave-f7th"
I20260812 06:18:14.224112 15253 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488419532-15253-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488419532-15253-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488419532-15253-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:18:14.242233 15253 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:14.242602 15253 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:14.242913 15253 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:14.243386 15253 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:14.243427 15253 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:14.243462 15253 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:14.243490 15253 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:14.248605 15253 rpc_server.cc:307] RPC server started. Bound to: 127.14.229.65:40865
I20260812 06:18:14.249714 15598 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.14.229.65:40865 every 8 connection(s)
I20260812 06:18:14.259418 15599 heartbeater.cc:344] Connected to a master server at 127.14.229.126:43557
I20260812 06:18:14.259527 15599 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:14.259783 15599 heartbeater.cc:507] Master 127.14.229.126:43557 requested a full tablet report, sending...
I20260812 06:18:14.260470 15470 ts_manager.cc:194] Registered new tserver with Master: 886118d1fe504c44bdc65ed04e4dc724 (127.14.229.65:40865)
I20260812 06:18:14.261435 15253 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.01214594s
I20260812 06:18:14.261462 15470 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:36924
I20260812 06:18:14.268535 15470 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:36926:
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:18:14.277539 15563 tablet_service.cc:1511] Processing CreateTablet for tablet 76108c8bd2cc4ac18c14a59243f1d9c8 (DEFAULT_TABLE table=heavy-update-compaction-test [id=21a5ab18296e401e88e4552006c1c840]), partition=
I20260812 06:18:14.277810 15563 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 76108c8bd2cc4ac18c14a59243f1d9c8. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:14.279843 15611 tablet_bootstrap.cc:492] T 76108c8bd2cc4ac18c14a59243f1d9c8 P 886118d1fe504c44bdc65ed04e4dc724: Bootstrap starting.
I20260812 06:18:14.280915 15611 tablet_bootstrap.cc:654] T 76108c8bd2cc4ac18c14a59243f1d9c8 P 886118d1fe504c44bdc65ed04e4dc724: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:14.282112 15611 tablet_bootstrap.cc:492] T 76108c8bd2cc4ac18c14a59243f1d9c8 P 886118d1fe504c44bdc65ed04e4dc724: No bootstrap required, opened a new log
I20260812 06:18:14.282208 15611 ts_tablet_manager.cc:1403] T 76108c8bd2cc4ac18c14a59243f1d9c8 P 886118d1fe504c44bdc65ed04e4dc724: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:14.282655 15611 raft_consensus.cc:359] T 76108c8bd2cc4ac18c14a59243f1d9c8 P 886118d1fe504c44bdc65ed04e4dc724 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "886118d1fe504c44bdc65ed04e4dc724" member_type: VOTER last_known_addr { host: "127.14.229.65" port: 40865 } }
I20260812 06:18:14.282768 15611 raft_consensus.cc:385] T 76108c8bd2cc4ac18c14a59243f1d9c8 P 886118d1fe504c44bdc65ed04e4dc724 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:14.282807 15611 raft_consensus.cc:740] T 76108c8bd2cc4ac18c14a59243f1d9c8 P 886118d1fe504c44bdc65ed04e4dc724 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 886118d1fe504c44bdc65ed04e4dc724, State: Initialized, Role: FOLLOWER
I20260812 06:18:14.282946 15611 consensus_queue.cc:260] T 76108c8bd2cc4ac18c14a59243f1d9c8 P 886118d1fe504c44bdc65ed04e4dc724 [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: "886118d1fe504c44bdc65ed04e4dc724" member_type: VOTER last_known_addr { host: "127.14.229.65" port: 40865 } }
I20260812 06:18:14.283032 15611 raft_consensus.cc:399] T 76108c8bd2cc4ac18c14a59243f1d9c8 P 886118d1fe504c44bdc65ed04e4dc724 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:14.283084 15611 raft_consensus.cc:493] T 76108c8bd2cc4ac18c14a59243f1d9c8 P 886118d1fe504c44bdc65ed04e4dc724 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:14.283135 15611 raft_consensus.cc:3060] T 76108c8bd2cc4ac18c14a59243f1d9c8 P 886118d1fe504c44bdc65ed04e4dc724 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:14.284082 15611 raft_consensus.cc:515] T 76108c8bd2cc4ac18c14a59243f1d9c8 P 886118d1fe504c44bdc65ed04e4dc724 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "886118d1fe504c44bdc65ed04e4dc724" member_type: VOTER last_known_addr { host: "127.14.229.65" port: 40865 } }
I20260812 06:18:14.284242 15611 leader_election.cc:304] T 76108c8bd2cc4ac18c14a59243f1d9c8 P 886118d1fe504c44bdc65ed04e4dc724 [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: 886118d1fe504c44bdc65ed04e4dc724; no voters: 
I20260812 06:18:14.284451 15611 leader_election.cc:290] T 76108c8bd2cc4ac18c14a59243f1d9c8 P 886118d1fe504c44bdc65ed04e4dc724 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:14.284614 15613 raft_consensus.cc:2804] T 76108c8bd2cc4ac18c14a59243f1d9c8 P 886118d1fe504c44bdc65ed04e4dc724 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:14.284817 15611 ts_tablet_manager.cc:1434] T 76108c8bd2cc4ac18c14a59243f1d9c8 P 886118d1fe504c44bdc65ed04e4dc724: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:14.284847 15599 heartbeater.cc:499] Master 127.14.229.126:43557 was elected leader, sending a full tablet report...
I20260812 06:18:14.284874 15613 raft_consensus.cc:697] T 76108c8bd2cc4ac18c14a59243f1d9c8 P 886118d1fe504c44bdc65ed04e4dc724 [term 1 LEADER]: Becoming Leader. State: Replica: 886118d1fe504c44bdc65ed04e4dc724, State: Running, Role: LEADER
I20260812 06:18:14.285175 15613 consensus_queue.cc:237] T 76108c8bd2cc4ac18c14a59243f1d9c8 P 886118d1fe504c44bdc65ed04e4dc724 [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: "886118d1fe504c44bdc65ed04e4dc724" member_type: VOTER last_known_addr { host: "127.14.229.65" port: 40865 } }
I20260812 06:18:14.286376 15470 catalog_manager.cc:5719] T 76108c8bd2cc4ac18c14a59243f1d9c8 P 886118d1fe504c44bdc65ed04e4dc724 reported cstate change: term changed from 0 to 1, leader changed from <none> to 886118d1fe504c44bdc65ed04e4dc724 (127.14.229.65). New cstate: current_term: 1 leader_uuid: "886118d1fe504c44bdc65ed04e4dc724" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "886118d1fe504c44bdc65ed04e4dc724" member_type: VOTER last_known_addr { host: "127.14.229.65" port: 40865 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:14.348374 15253 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.055s	user 0.010s	sys 0.014s
I20260812 06:18:14.500180 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling FlushMRSOp(76108c8bd2cc4ac18c14a59243f1d9c8): perf score=19.054940
I20260812 06:18:14.662465 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: FlushMRSOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.162s	user 0.103s	sys 0.052s Metrics: {"bytes_written":12307492,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":28,"dirs.run_cpu_time_us":178,"dirs.run_wall_time_us":913,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":39388,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:18:14.663025 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling LogGCOp(76108c8bd2cc4ac18c14a59243f1d9c8): free 20743880 bytes of WAL
I20260812 06:18:14.663223 15540 log_reader.cc:385] T 76108c8bd2cc4ac18c14a59243f1d9c8: removed 2 log segments from log reader
I20260812 06:18:14.663271 15540 log.cc:1079] T 76108c8bd2cc4ac18c14a59243f1d9c8 P 886118d1fe504c44bdc65ed04e4dc724: Deleting log segment in path: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488419532-15253-0/minicluster-data/ts-0-root/wals/76108c8bd2cc4ac18c14a59243f1d9c8/wal-000000001 (ops 1-6)
I20260812 06:18:14.663311 15540 log.cc:1079] T 76108c8bd2cc4ac18c14a59243f1d9c8 P 886118d1fe504c44bdc65ed04e4dc724: Deleting log segment in path: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488419532-15253-0/minicluster-data/ts-0-root/wals/76108c8bd2cc4ac18c14a59243f1d9c8/wal-000000002 (ops 7-11)
I20260812 06:18:14.666623 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: LogGCOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:18:14.666985 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling UndoDeltaBlockGCOp(76108c8bd2cc4ac18c14a59243f1d9c8): 16411392 bytes on disk
I20260812 06:18:14.667481 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: UndoDeltaBlockGCOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":81,"lbm_reads_lt_1ms":4}
I20260812 06:18:14.667904 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8): perf score=2.188937
I20260812 06:18:14.684265 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.016s	user 0.004s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6747,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:14.684767 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling MajorDeltaCompactionOp(76108c8bd2cc4ac18c14a59243f1d9c8): perf score=1.000000
I20260812 06:18:14.845726 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: MajorDeltaCompactionOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.160s	user 0.107s	sys 0.053s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":372,"lbm_read_time_us":11306,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23591,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5120,"thread_start_us":264,"threads_started":5,"update_count":2000}
I20260812 06:18:14.846299 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8): perf score=10.126437
I20260812 06:18:14.878232 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.032s	user 0.025s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13963,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":1500}
I20260812 06:18:14.878664 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8): perf score=2.188937
I20260812 06:18:14.891110 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4829,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:14.891535 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling MajorDeltaCompactionOp(76108c8bd2cc4ac18c14a59243f1d9c8): perf score=1.000000
I20260812 06:18:15.023465 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: MajorDeltaCompactionOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.132s	user 0.106s	sys 0.025s 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":395,"lbm_read_time_us":8829,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23952,"lbm_writes_lt_1ms":443,"mutex_wait_us":34,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13184,"update_count":2000}
I20260812 06:18:15.024174 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8): perf score=10.126437
I20260812 06:18:15.066555 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.042s	user 0.022s	sys 0.007s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14052,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:15.066993 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8): perf score=2.188937
I20260812 06:18:15.079397 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.012s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4724,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:15.079949 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling MajorDeltaCompactionOp(76108c8bd2cc4ac18c14a59243f1d9c8): perf score=1.000000
I20260812 06:18:15.214359 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: MajorDeltaCompactionOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.134s	user 0.106s	sys 0.024s 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,"dirs.run_cpu_time_us":1474,"dirs.run_wall_time_us":10702,"lbm_read_time_us":8897,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24329,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:18:15.214869 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8): perf score=10.126437
I20260812 06:18:15.256325 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.041s	user 0.022s	sys 0.019s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":13935,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:15.256894 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8): perf score=2.188937
I20260812 06:18:15.270473 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.013s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5304,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:15.270916 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling MajorDeltaCompactionOp(76108c8bd2cc4ac18c14a59243f1d9c8): perf score=1.000000
I20260812 06:18:15.440411 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: MajorDeltaCompactionOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.169s	user 0.121s	sys 0.043s 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":105,"lbm_read_time_us":11461,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25024,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":2000}
I20260812 06:18:15.440999 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8): perf score=11.118625
I20260812 06:18:15.483065 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.042s	user 0.026s	sys 0.012s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":17563,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:15.483639 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8): perf score=2.188937
I20260812 06:18:15.508550 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.025s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3931,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:15.508997 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8): perf score=2.188937
I20260812 06:18:15.517962 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.009s	user 0.004s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3243,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:15.518328 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling MajorDeltaCompactionOp(76108c8bd2cc4ac18c14a59243f1d9c8): perf score=1.000000
I20260812 06:18:15.682114 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: MajorDeltaCompactionOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.164s	user 0.131s	sys 0.030s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":313,"lbm_read_time_us":10732,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30811,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:15.682749 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8): perf score=10.126437
I20260812 06:18:15.727003 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.044s	user 0.012s	sys 0.021s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":14798,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:15.727516 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8): perf score=2.188937
I20260812 06:18:15.742655 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.015s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5340,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:15.743266 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling MajorDeltaCompactionOp(76108c8bd2cc4ac18c14a59243f1d9c8): perf score=1.000000
I20260812 06:18:15.869930 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: MajorDeltaCompactionOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.126s	user 0.108s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1042,"lbm_read_time_us":8497,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21831,"lbm_writes_lt_1ms":443,"mutex_wait_us":429,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:18:15.870512 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8): perf score=10.126437
I20260812 06:18:15.911808 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.041s	user 0.034s	sys 0.000s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14510,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:15.912313 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8): perf score=2.188937
I20260812 06:18:15.926189 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.014s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5128,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:15.926635 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling FlushMRSOp(76108c8bd2cc4ac18c14a59243f1d9c8): perf score=1.000000
I20260812 06:18:15.956466 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: FlushMRSOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.030s	user 0.028s	sys 0.001s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":929,"dirs.run_cpu_time_us":232,"dirs.run_wall_time_us":1316,"drs_written":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1578,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29,"spinlock_wait_cycles":7040}
I20260812 06:18:15.957145 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling LogGCOp(76108c8bd2cc4ac18c14a59243f1d9c8): free 112239310 bytes of WAL
I20260812 06:18:15.957360 15540 log_reader.cc:385] T 76108c8bd2cc4ac18c14a59243f1d9c8: removed 11 log segments from log reader
I20260812 06:18:15.957407 15540 log.cc:1079] T 76108c8bd2cc4ac18c14a59243f1d9c8 P 886118d1fe504c44bdc65ed04e4dc724: Deleting log segment in path: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488419532-15253-0/minicluster-data/ts-0-root/wals/76108c8bd2cc4ac18c14a59243f1d9c8/wal-000000003 (ops 12-16)
I20260812 06:18:15.957499 15540 log.cc:1079] T 76108c8bd2cc4ac18c14a59243f1d9c8 P 886118d1fe504c44bdc65ed04e4dc724: Deleting log segment in path: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488419532-15253-0/minicluster-data/ts-0-root/wals/76108c8bd2cc4ac18c14a59243f1d9c8/wal-000000004 (ops 17-21)
I20260812 06:18:15.957537 15540 log.cc:1079] T 76108c8bd2cc4ac18c14a59243f1d9c8 P 886118d1fe504c44bdc65ed04e4dc724: Deleting log segment in path: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488419532-15253-0/minicluster-data/ts-0-root/wals/76108c8bd2cc4ac18c14a59243f1d9c8/wal-000000005 (ops 22-26)
I20260812 06:18:15.957559 15540 log.cc:1079] T 76108c8bd2cc4ac18c14a59243f1d9c8 P 886118d1fe504c44bdc65ed04e4dc724: Deleting log segment in path: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488419532-15253-0/minicluster-data/ts-0-root/wals/76108c8bd2cc4ac18c14a59243f1d9c8/wal-000000006 (ops 27-31)
I20260812 06:18:15.957628 15540 log.cc:1079] T 76108c8bd2cc4ac18c14a59243f1d9c8 P 886118d1fe504c44bdc65ed04e4dc724: Deleting log segment in path: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488419532-15253-0/minicluster-data/ts-0-root/wals/76108c8bd2cc4ac18c14a59243f1d9c8/wal-000000007 (ops 32-36)
I20260812 06:18:15.957662 15540 log.cc:1079] T 76108c8bd2cc4ac18c14a59243f1d9c8 P 886118d1fe504c44bdc65ed04e4dc724: Deleting log segment in path: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488419532-15253-0/minicluster-data/ts-0-root/wals/76108c8bd2cc4ac18c14a59243f1d9c8/wal-000000008 (ops 37-40)
I20260812 06:18:15.957717 15540 log.cc:1079] T 76108c8bd2cc4ac18c14a59243f1d9c8 P 886118d1fe504c44bdc65ed04e4dc724: Deleting log segment in path: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488419532-15253-0/minicluster-data/ts-0-root/wals/76108c8bd2cc4ac18c14a59243f1d9c8/wal-000000009 (ops 41-45)
I20260812 06:18:15.957753 15540 log.cc:1079] T 76108c8bd2cc4ac18c14a59243f1d9c8 P 886118d1fe504c44bdc65ed04e4dc724: Deleting log segment in path: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488419532-15253-0/minicluster-data/ts-0-root/wals/76108c8bd2cc4ac18c14a59243f1d9c8/wal-000000010 (ops 46-50)
I20260812 06:18:15.957808 15540 log.cc:1079] T 76108c8bd2cc4ac18c14a59243f1d9c8 P 886118d1fe504c44bdc65ed04e4dc724: Deleting log segment in path: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488419532-15253-0/minicluster-data/ts-0-root/wals/76108c8bd2cc4ac18c14a59243f1d9c8/wal-000000011 (ops 51-55)
I20260812 06:18:15.957839 15540 log.cc:1079] T 76108c8bd2cc4ac18c14a59243f1d9c8 P 886118d1fe504c44bdc65ed04e4dc724: Deleting log segment in path: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488419532-15253-0/minicluster-data/ts-0-root/wals/76108c8bd2cc4ac18c14a59243f1d9c8/wal-000000012 (ops 56-60)
I20260812 06:18:15.957893 15540 log.cc:1079] T 76108c8bd2cc4ac18c14a59243f1d9c8 P 886118d1fe504c44bdc65ed04e4dc724: Deleting log segment in path: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488419532-15253-0/minicluster-data/ts-0-root/wals/76108c8bd2cc4ac18c14a59243f1d9c8/wal-000000013 (ops 61-65)
I20260812 06:18:15.982410 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: LogGCOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.025s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:18:15.982965 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8): perf score=2.188937
I20260812 06:18:16.002605 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.019s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4792,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:16.003039 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling LogGCOp(76108c8bd2cc4ac18c14a59243f1d9c8): free 12017932 bytes of WAL
I20260812 06:18:16.003223 15540 log_reader.cc:385] T 76108c8bd2cc4ac18c14a59243f1d9c8: removed 1 log segments from log reader
I20260812 06:18:16.003264 15540 log.cc:1079] T 76108c8bd2cc4ac18c14a59243f1d9c8 P 886118d1fe504c44bdc65ed04e4dc724: Deleting log segment in path: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488419532-15253-0/minicluster-data/ts-0-root/wals/76108c8bd2cc4ac18c14a59243f1d9c8/wal-000000014 (ops 66-70)
I20260812 06:18:16.005089 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: LogGCOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:18:16.005357 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling UndoDeltaBlockGCOp(76108c8bd2cc4ac18c14a59243f1d9c8): 463 bytes on disk
I20260812 06:18:16.005713 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: UndoDeltaBlockGCOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4}
I20260812 06:18:16.006108 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8): perf score=2.188937
I20260812 06:18:16.015793 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.010s	user 0.008s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3429,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:16.016170 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling MajorDeltaCompactionOp(76108c8bd2cc4ac18c14a59243f1d9c8): perf score=1.000000
I20260812 06:18:16.215863 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: MajorDeltaCompactionOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.200s	user 0.153s	sys 0.043s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877339,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1419,"lbm_read_time_us":13244,"lbm_reads_lt_1ms":674,"lbm_write_time_us":42934,"lbm_writes_lt_1ms":643,"mutex_wait_us":1051,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":5504,"thread_start_us":70,"threads_started":1,"update_count":3000}
I20260812 06:18:16.216413 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8): perf score=14.095187
I20260812 06:18:16.266373 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.048s	user 0.027s	sys 0.016s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":20080,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:16.266959 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8): perf score=2.188937
I20260812 06:18:16.277706 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3925,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:16.278264 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling MajorDeltaCompactionOp(76108c8bd2cc4ac18c14a59243f1d9c8): perf score=1.000000
I20260812 06:18:16.451154 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: MajorDeltaCompactionOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.173s	user 0.123s	sys 0.049s 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":804,"lbm_read_time_us":10472,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33763,"lbm_writes_lt_1ms":543,"mutex_wait_us":344,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":26880,"update_count":2500}
I20260812 06:18:16.451911 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8): perf score=10.126437
I20260812 06:18:16.504448 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.052s	user 0.025s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18393,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:16.504962 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8): perf score=2.188937
I20260812 06:18:16.515806 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3955,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:16.516247 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling MajorDeltaCompactionOp(76108c8bd2cc4ac18c14a59243f1d9c8): perf score=1.000000
I20260812 06:18:16.675964 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: MajorDeltaCompactionOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.160s	user 0.098s	sys 0.060s 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":1102,"lbm_read_time_us":12525,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24323,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7680,"update_count":2000}
I20260812 06:18:16.676730 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8): perf score=10.126437
I20260812 06:18:16.717635 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.041s	user 0.026s	sys 0.012s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":17609,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:16.718124 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8): perf score=2.188937
I20260812 06:18:16.733300 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.015s	user 0.001s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5560,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:16.733855 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling MajorDeltaCompactionOp(76108c8bd2cc4ac18c14a59243f1d9c8): perf score=1.000000
I20260812 06:18:16.890892 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: MajorDeltaCompactionOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.156s	user 0.112s	sys 0.035s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":586,"lbm_read_time_us":8910,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27579,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":189,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2000}
I20260812 06:18:16.891392 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8): perf score=10.126437
I20260812 06:18:16.921626 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.030s	user 0.008s	sys 0.019s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":12673,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:16.922170 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8): perf score=2.188937
I20260812 06:18:16.938181 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.016s	user 0.006s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6105,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:16.938706 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling MajorDeltaCompactionOp(76108c8bd2cc4ac18c14a59243f1d9c8): perf score=1.000000
I20260812 06:18:17.108728 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: MajorDeltaCompactionOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.170s	user 0.115s	sys 0.030s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":321,"lbm_read_time_us":10294,"lbm_reads_lt_1ms":464,"lbm_write_time_us":30005,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:17.109458 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8): perf score=14.095187
I20260812 06:18:17.166795 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.057s	user 0.042s	sys 0.004s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":21841,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:17.167336 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8): perf score=2.188937
I20260812 06:18:17.182521 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5533,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:17.183126 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling MajorDeltaCompactionOp(76108c8bd2cc4ac18c14a59243f1d9c8): perf score=1.000000
I20260812 06:18:17.363385 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: MajorDeltaCompactionOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.180s	user 0.138s	sys 0.041s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774692,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":604,"lbm_read_time_us":11308,"lbm_reads_lt_1ms":572,"lbm_write_time_us":36151,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11392,"update_count":2500}
I20260812 06:18:17.363937 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8): perf score=14.095187
I20260812 06:18:17.429193 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.065s	user 0.029s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23161,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:18:17.429766 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8): perf score=2.188937
I20260812 06:18:17.447006 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.017s	user 0.014s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6297,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:17.447702 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling FlushMRSOp(76108c8bd2cc4ac18c14a59243f1d9c8): perf score=1.000000
I20260812 06:18:17.481657 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: FlushMRSOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.034s	user 0.025s	sys 0.005s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":67,"dirs.run_cpu_time_us":202,"dirs.run_wall_time_us":1777,"drs_written":1,"lbm_read_time_us":787,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2734,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29,"spinlock_wait_cycles":11008}
I20260812 06:18:17.482247 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling LogGCOp(76108c8bd2cc4ac18c14a59243f1d9c8): free 112692315 bytes of WAL
I20260812 06:18:17.482443 15540 log_reader.cc:385] T 76108c8bd2cc4ac18c14a59243f1d9c8: removed 11 log segments from log reader
I20260812 06:18:17.482486 15540 log.cc:1079] T 76108c8bd2cc4ac18c14a59243f1d9c8 P 886118d1fe504c44bdc65ed04e4dc724: Deleting log segment in path: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488419532-15253-0/minicluster-data/ts-0-root/wals/76108c8bd2cc4ac18c14a59243f1d9c8/wal-000000015 (ops 71-75)
I20260812 06:18:17.482513 15540 log.cc:1079] T 76108c8bd2cc4ac18c14a59243f1d9c8 P 886118d1fe504c44bdc65ed04e4dc724: Deleting log segment in path: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488419532-15253-0/minicluster-data/ts-0-root/wals/76108c8bd2cc4ac18c14a59243f1d9c8/wal-000000016 (ops 76-80)
I20260812 06:18:17.482544 15540 log.cc:1079] T 76108c8bd2cc4ac18c14a59243f1d9c8 P 886118d1fe504c44bdc65ed04e4dc724: Deleting log segment in path: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488419532-15253-0/minicluster-data/ts-0-root/wals/76108c8bd2cc4ac18c14a59243f1d9c8/wal-000000017 (ops 81-85)
I20260812 06:18:17.482569 15540 log.cc:1079] T 76108c8bd2cc4ac18c14a59243f1d9c8 P 886118d1fe504c44bdc65ed04e4dc724: Deleting log segment in path: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488419532-15253-0/minicluster-data/ts-0-root/wals/76108c8bd2cc4ac18c14a59243f1d9c8/wal-000000018 (ops 86-90)
I20260812 06:18:17.482594 15540 log.cc:1079] T 76108c8bd2cc4ac18c14a59243f1d9c8 P 886118d1fe504c44bdc65ed04e4dc724: Deleting log segment in path: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488419532-15253-0/minicluster-data/ts-0-root/wals/76108c8bd2cc4ac18c14a59243f1d9c8/wal-000000019 (ops 91-95)
I20260812 06:18:17.482671 15540 log.cc:1079] T 76108c8bd2cc4ac18c14a59243f1d9c8 P 886118d1fe504c44bdc65ed04e4dc724: Deleting log segment in path: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488419532-15253-0/minicluster-data/ts-0-root/wals/76108c8bd2cc4ac18c14a59243f1d9c8/wal-000000020 (ops 96-100)
I20260812 06:18:17.482703 15540 log.cc:1079] T 76108c8bd2cc4ac18c14a59243f1d9c8 P 886118d1fe504c44bdc65ed04e4dc724: Deleting log segment in path: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488419532-15253-0/minicluster-data/ts-0-root/wals/76108c8bd2cc4ac18c14a59243f1d9c8/wal-000000021 (ops 101-105)
I20260812 06:18:17.482728 15540 log.cc:1079] T 76108c8bd2cc4ac18c14a59243f1d9c8 P 886118d1fe504c44bdc65ed04e4dc724: Deleting log segment in path: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488419532-15253-0/minicluster-data/ts-0-root/wals/76108c8bd2cc4ac18c14a59243f1d9c8/wal-000000022 (ops 106-110)
I20260812 06:18:17.482748 15540 log.cc:1079] T 76108c8bd2cc4ac18c14a59243f1d9c8 P 886118d1fe504c44bdc65ed04e4dc724: Deleting log segment in path: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488419532-15253-0/minicluster-data/ts-0-root/wals/76108c8bd2cc4ac18c14a59243f1d9c8/wal-000000023 (ops 111-115)
I20260812 06:18:17.482767 15540 log.cc:1079] T 76108c8bd2cc4ac18c14a59243f1d9c8 P 886118d1fe504c44bdc65ed04e4dc724: Deleting log segment in path: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488419532-15253-0/minicluster-data/ts-0-root/wals/76108c8bd2cc4ac18c14a59243f1d9c8/wal-000000024 (ops 116-120)
I20260812 06:18:17.482788 15540 log.cc:1079] T 76108c8bd2cc4ac18c14a59243f1d9c8 P 886118d1fe504c44bdc65ed04e4dc724: Deleting log segment in path: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488419532-15253-0/minicluster-data/ts-0-root/wals/76108c8bd2cc4ac18c14a59243f1d9c8/wal-000000025 (ops 121-125)
I20260812 06:18:17.503785 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: LogGCOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.021s	user 0.000s	sys 0.020s Metrics: {}
I20260812 06:18:17.504415 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling UndoDeltaBlockGCOp(76108c8bd2cc4ac18c14a59243f1d9c8): 462 bytes on disk
I20260812 06:18:17.504830 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: UndoDeltaBlockGCOp(76108c8bd2cc4ac18c14a59243f1d9c8) 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:18:17.505296 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8): perf score=2.188937
I20260812 06:18:17.530068 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.022s	user 0.008s	sys 0.003s Metrics: {"bytes_written":4430855,"delete_count":0,"lbm_write_time_us":4812,"lbm_writes_lt_1ms":111,"reinsert_count":0,"update_count":540}
I20260812 06:18:17.530552 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8): perf score=2.188937
I20260812 06:18:17.547020 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.016s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3774459,"delete_count":0,"lbm_write_time_us":4981,"lbm_writes_lt_1ms":95,"reinsert_count":0,"update_count":460}
I20260812 06:18:17.547722 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling MajorDeltaCompactionOp(76108c8bd2cc4ac18c14a59243f1d9c8): perf score=1.000000
I20260812 06:18:17.782058 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: MajorDeltaCompactionOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.234s	user 0.137s	sys 0.089s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979746,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":318,"lbm_read_time_us":15467,"lbm_reads_lt_1ms":774,"lbm_write_time_us":42647,"lbm_writes_lt_1ms":743,"mutex_wait_us":18,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":11904,"thread_start_us":64,"threads_started":1,"update_count":3500}
I20260812 06:18:17.782591 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8): perf score=14.095187
I20260812 06:18:17.824442 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.042s	user 0.021s	sys 0.019s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":18702,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:17.824998 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8): perf score=2.188937
I20260812 06:18:17.838887 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.014s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4067,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:17.839391 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling MajorDeltaCompactionOp(76108c8bd2cc4ac18c14a59243f1d9c8): perf score=1.000000
I20260812 06:18:17.993649 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: MajorDeltaCompactionOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.154s	user 0.127s	sys 0.024s 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":221,"lbm_read_time_us":10561,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28065,"lbm_writes_lt_1ms":543,"mutex_wait_us":20,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3200,"update_count":2500}
I20260812 06:18:17.994277 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8): perf score=10.126437
I20260812 06:18:18.031471 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.037s	user 0.026s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16179,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:18.032014 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling MajorDeltaCompactionOp(76108c8bd2cc4ac18c14a59243f1d9c8): perf score=1.000000
I20260812 06:18:18.182914 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: MajorDeltaCompactionOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.151s	user 0.094s	sys 0.041s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569746,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":529,"lbm_read_time_us":10772,"lbm_reads_lt_1ms":367,"lbm_write_time_us":21537,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":342,"mutex_wait_us":25,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":3712,"update_count":1500}
I20260812 06:18:18.183739 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8): perf score=10.126437
I20260812 06:18:18.215974 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.032s	user 0.023s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13387,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:18.216513 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling MajorDeltaCompactionOp(76108c8bd2cc4ac18c14a59243f1d9c8): perf score=1.000000
I20260812 06:18:18.344283 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: MajorDeltaCompactionOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.128s	user 0.094s	sys 0.020s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569746,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":391,"lbm_read_time_us":6509,"lbm_reads_lt_1ms":367,"lbm_write_time_us":20218,"lbm_writes_lt_1ms":343,"mutex_wait_us":224,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":3456,"update_count":1500}
I20260812 06:18:18.346836 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8): perf score=10.126437
I20260812 06:18:18.391814 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.045s	user 0.019s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14477,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:18.392445 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8): perf score=2.188937
I20260812 06:18:18.412364 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.020s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7758,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:18.412966 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling MajorDeltaCompactionOp(76108c8bd2cc4ac18c14a59243f1d9c8): perf score=1.000000
I20260812 06:18:18.543969 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: MajorDeltaCompactionOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.131s	user 0.110s	sys 0.019s 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":132,"lbm_read_time_us":9454,"lbm_reads_lt_1ms":468,"lbm_write_time_us":25276,"lbm_writes_lt_1ms":443,"mutex_wait_us":57,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11136,"update_count":2000}
I20260812 06:18:18.544577 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8): perf score=10.126437
I20260812 06:18:18.589677 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.045s	user 0.026s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14730,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:18.590232 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling MajorDeltaCompactionOp(76108c8bd2cc4ac18c14a59243f1d9c8): perf score=1.000000
I20260812 06:18:18.725904 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: MajorDeltaCompactionOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.136s	user 0.109s	sys 0.025s 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":155,"lbm_read_time_us":8885,"lbm_reads_lt_1ms":363,"lbm_write_time_us":21057,"lbm_writes_lt_1ms":343,"mutex_wait_us":54,"peak_mem_usage":38262756,"reinsert_count":0,"update_count":1500}
I20260812 06:18:18.726483 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8): perf score=10.126437
I20260812 06:18:18.771138 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.044s	user 0.024s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16523,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:18.771754 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8): perf score=2.188937
I20260812 06:18:18.783253 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4394,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:18.783813 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling MajorDeltaCompactionOp(76108c8bd2cc4ac18c14a59243f1d9c8): perf score=1.000000
I20260812 06:18:18.930899 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: MajorDeltaCompactionOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.147s	user 0.107s	sys 0.033s 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":182,"lbm_read_time_us":10972,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25654,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:18:18.931531 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8): perf score=10.126437
I20260812 06:18:18.984162 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.052s	user 0.028s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16395,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:18.984742 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8): perf score=2.188937
I20260812 06:18:18.994755 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3642,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:18.995182 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling FlushMRSOp(76108c8bd2cc4ac18c14a59243f1d9c8): perf score=1.000000
I20260812 06:18:19.028182 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: FlushMRSOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.033s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":67,"dirs.run_cpu_time_us":214,"dirs.run_wall_time_us":1262,"drs_written":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1222,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:19.028906 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling LogGCOp(76108c8bd2cc4ac18c14a59243f1d9c8): free 112239597 bytes of WAL
I20260812 06:18:19.029101 15540 log_reader.cc:385] T 76108c8bd2cc4ac18c14a59243f1d9c8: removed 11 log segments from log reader
I20260812 06:18:19.029147 15540 log.cc:1079] T 76108c8bd2cc4ac18c14a59243f1d9c8 P 886118d1fe504c44bdc65ed04e4dc724: Deleting log segment in path: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488419532-15253-0/minicluster-data/ts-0-root/wals/76108c8bd2cc4ac18c14a59243f1d9c8/wal-000000026 (ops 126-130)
I20260812 06:18:19.029237 15540 log.cc:1079] T 76108c8bd2cc4ac18c14a59243f1d9c8 P 886118d1fe504c44bdc65ed04e4dc724: Deleting log segment in path: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488419532-15253-0/minicluster-data/ts-0-root/wals/76108c8bd2cc4ac18c14a59243f1d9c8/wal-000000027 (ops 131-134)
I20260812 06:18:19.029274 15540 log.cc:1079] T 76108c8bd2cc4ac18c14a59243f1d9c8 P 886118d1fe504c44bdc65ed04e4dc724: Deleting log segment in path: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488419532-15253-0/minicluster-data/ts-0-root/wals/76108c8bd2cc4ac18c14a59243f1d9c8/wal-000000028 (ops 135-139)
I20260812 06:18:19.029296 15540 log.cc:1079] T 76108c8bd2cc4ac18c14a59243f1d9c8 P 886118d1fe504c44bdc65ed04e4dc724: Deleting log segment in path: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488419532-15253-0/minicluster-data/ts-0-root/wals/76108c8bd2cc4ac18c14a59243f1d9c8/wal-000000029 (ops 140-144)
I20260812 06:18:19.029354 15540 log.cc:1079] T 76108c8bd2cc4ac18c14a59243f1d9c8 P 886118d1fe504c44bdc65ed04e4dc724: Deleting log segment in path: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488419532-15253-0/minicluster-data/ts-0-root/wals/76108c8bd2cc4ac18c14a59243f1d9c8/wal-000000030 (ops 145-149)
I20260812 06:18:19.029390 15540 log.cc:1079] T 76108c8bd2cc4ac18c14a59243f1d9c8 P 886118d1fe504c44bdc65ed04e4dc724: Deleting log segment in path: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488419532-15253-0/minicluster-data/ts-0-root/wals/76108c8bd2cc4ac18c14a59243f1d9c8/wal-000000031 (ops 150-154)
I20260812 06:18:19.029412 15540 log.cc:1079] T 76108c8bd2cc4ac18c14a59243f1d9c8 P 886118d1fe504c44bdc65ed04e4dc724: Deleting log segment in path: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488419532-15253-0/minicluster-data/ts-0-root/wals/76108c8bd2cc4ac18c14a59243f1d9c8/wal-000000032 (ops 155-159)
I20260812 06:18:19.029439 15540 log.cc:1079] T 76108c8bd2cc4ac18c14a59243f1d9c8 P 886118d1fe504c44bdc65ed04e4dc724: Deleting log segment in path: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488419532-15253-0/minicluster-data/ts-0-root/wals/76108c8bd2cc4ac18c14a59243f1d9c8/wal-000000033 (ops 160-164)
I20260812 06:18:19.029495 15540 log.cc:1079] T 76108c8bd2cc4ac18c14a59243f1d9c8 P 886118d1fe504c44bdc65ed04e4dc724: Deleting log segment in path: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488419532-15253-0/minicluster-data/ts-0-root/wals/76108c8bd2cc4ac18c14a59243f1d9c8/wal-000000034 (ops 165-169)
I20260812 06:18:19.029531 15540 log.cc:1079] T 76108c8bd2cc4ac18c14a59243f1d9c8 P 886118d1fe504c44bdc65ed04e4dc724: Deleting log segment in path: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488419532-15253-0/minicluster-data/ts-0-root/wals/76108c8bd2cc4ac18c14a59243f1d9c8/wal-000000035 (ops 170-174)
I20260812 06:18:19.029583 15540 log.cc:1079] T 76108c8bd2cc4ac18c14a59243f1d9c8 P 886118d1fe504c44bdc65ed04e4dc724: Deleting log segment in path: /tmp/dist-test-task0uzGN6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488419532-15253-0/minicluster-data/ts-0-root/wals/76108c8bd2cc4ac18c14a59243f1d9c8/wal-000000036 (ops 175-179)
I20260812 06:18:19.053054 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: LogGCOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.024s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:18:19.053413 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling UndoDeltaBlockGCOp(76108c8bd2cc4ac18c14a59243f1d9c8): 448 bytes on disk
I20260812 06:18:19.053792 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: UndoDeltaBlockGCOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4}
I20260812 06:18:19.054342 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8): perf score=2.188937
I20260812 06:18:19.072747 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.018s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4408,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:19.073163 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8): perf score=2.188937
I20260812 06:18:19.082605 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.009s	user 0.004s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3644,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:19.082988 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling MajorDeltaCompactionOp(76108c8bd2cc4ac18c14a59243f1d9c8): perf score=1.000000
I20260812 06:18:19.254935 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: MajorDeltaCompactionOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.172s	user 0.148s	sys 0.020s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877338,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":840,"lbm_read_time_us":11594,"lbm_reads_lt_1ms":674,"lbm_write_time_us":32646,"lbm_writes_lt_1ms":643,"mutex_wait_us":452,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1792,"thread_start_us":94,"threads_started":1,"update_count":3000}
I20260812 06:18:19.255695 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8): perf score=11.118625
I20260812 06:18:19.295310 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.039s	user 0.024s	sys 0.012s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":17304,"lbm_writes_lt_1ms":313,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":1550}
I20260812 06:18:19.295957 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8): perf score=2.188937
I20260812 06:18:19.307920 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4507,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:19.308588 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling MajorDeltaCompactionOp(76108c8bd2cc4ac18c14a59243f1d9c8): perf score=1.000000
I20260812 06:18:19.443688 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: MajorDeltaCompactionOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.135s	user 0.104s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":119,"lbm_read_time_us":8515,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26294,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":30,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":52096,"update_count":2000}
I20260812 06:18:19.444252 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8): perf score=11.118625
I20260812 06:18:19.462633 15253 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.108s	user 1.795s	sys 0.169s
I20260812 06:18:19.477999 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.034s	user 0.029s	sys 0.004s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":15874,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:19.478564 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8): perf score=2.188937
I20260812 06:18:19.489035 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: FlushDeltaMemStoresOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3913,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:19.489456 15600 maintenance_manager.cc:419] P 886118d1fe504c44bdc65ed04e4dc724: Scheduling MajorDeltaCompactionOp(76108c8bd2cc4ac18c14a59243f1d9c8): perf score=1.000000
I20260812 06:18:19.499764 15253 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.036s	user 0.002s	sys 0.000s
I20260812 06:18:19.500249 15253 tablet_server.cc:179] TabletServer@127.14.229.65:0 shutting down...
I20260812 06:18:19.617532 15540 maintenance_manager.cc:643] P 886118d1fe504c44bdc65ed04e4dc724: MajorDeltaCompactionOp(76108c8bd2cc4ac18c14a59243f1d9c8) complete. Timing: real 0.128s	user 0.092s	sys 0.036s Metrics: {"cfile_cache_hit":30,"cfile_cache_hit_bytes":4262390,"cfile_cache_miss":402,"cfile_cache_miss_bytes":16409877,"cfile_init":4,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":582,"lbm_read_time_us":7263,"lbm_reads_lt_1ms":418,"lbm_write_time_us":22219,"lbm_writes_lt_1ms":443,"mutex_wait_us":212,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:19.618520 15253 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:19.618741 15253 tablet_replica.cc:333] T 76108c8bd2cc4ac18c14a59243f1d9c8 P 886118d1fe504c44bdc65ed04e4dc724: stopping tablet replica
I20260812 06:18:19.618887 15253 raft_consensus.cc:2243] T 76108c8bd2cc4ac18c14a59243f1d9c8 P 886118d1fe504c44bdc65ed04e4dc724 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:19.619028 15253 raft_consensus.cc:2272] T 76108c8bd2cc4ac18c14a59243f1d9c8 P 886118d1fe504c44bdc65ed04e4dc724 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:19.622844 15253 tablet_server.cc:196] TabletServer@127.14.229.65:0 shutdown complete.
I20260812 06:18:19.655364 15253 master.cc:562] Master@127.14.229.126:43557 shutting down...
I20260812 06:18:19.658882 15253 raft_consensus.cc:2243] T 00000000000000000000000000000000 P af83a4a283ed456aa15485a074e13fca [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:19.659051 15253 raft_consensus.cc:2272] T 00000000000000000000000000000000 P af83a4a283ed456aa15485a074e13fca [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:19.659113 15253 tablet_replica.cc:333] T 00000000000000000000000000000000 P af83a4a283ed456aa15485a074e13fca: stopping tablet replica
I20260812 06:18:19.671389 15253 master.cc:584] Master@127.14.229.126:43557 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5636 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11315 ms total)

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