[==========] 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:39.878456 27570 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.26.236.190:35231
I20260812 06:18:39.879521 27570 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:39.880123 27570 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:39.886569 27580 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:39.886564 27577 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:39.886795 27570 server_base.cc:1061] running on GCE node
W20260812 06:18:39.886835 27578 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:39.887287 27570 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:39.887420 27570 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:39.887468 27570 hybrid_clock.cc:648] HybridClock initialized: now 1786515519887465 us; error 0 us; skew 500 ppm
I20260812 06:18:39.889199 27570 webserver.cc:533] Webserver started at http://127.26.236.190:43403/ using document root <none> and password file <none>
I20260812 06:18:39.889742 27570 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:39.889832 27570 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:39.890092 27570 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:39.891750 27570 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519867826-27570-0/minicluster-data/master-0-root/instance:
uuid: "a063ad9983a543b7a8ccebc1f8bb201f"
format_stamp: "Formatted at 2026-08-12 06:18:39 on dist-test-slave-gmjp"
I20260812 06:18:39.895287 27570 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:18:39.897367 27591 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:39.898306 27570 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:18:39.898450 27570 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519867826-27570-0/minicluster-data/master-0-root
uuid: "a063ad9983a543b7a8ccebc1f8bb201f"
format_stamp: "Formatted at 2026-08-12 06:18:39 on dist-test-slave-gmjp"
I20260812 06:18:39.898568 27570 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519867826-27570-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519867826-27570-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519867826-27570-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:39.928402 27570 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:39.929085 27570 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:39.929277 27570 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:39.936615 27570 rpc_server.cc:307] RPC server started. Bound to: 127.26.236.190:35231
I20260812 06:18:39.936620 27684 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.26.236.190:35231 every 8 connection(s)
I20260812 06:18:39.938846 27685 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:39.944340 27685 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a063ad9983a543b7a8ccebc1f8bb201f: Bootstrap starting.
I20260812 06:18:39.946700 27685 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P a063ad9983a543b7a8ccebc1f8bb201f: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:39.947623 27685 log.cc:826] T 00000000000000000000000000000000 P a063ad9983a543b7a8ccebc1f8bb201f: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:39.949307 27685 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a063ad9983a543b7a8ccebc1f8bb201f: No bootstrap required, opened a new log
I20260812 06:18:39.951967 27685 raft_consensus.cc:359] T 00000000000000000000000000000000 P a063ad9983a543b7a8ccebc1f8bb201f [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a063ad9983a543b7a8ccebc1f8bb201f" member_type: VOTER }
I20260812 06:18:39.952119 27685 raft_consensus.cc:385] T 00000000000000000000000000000000 P a063ad9983a543b7a8ccebc1f8bb201f [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:39.952252 27685 raft_consensus.cc:740] T 00000000000000000000000000000000 P a063ad9983a543b7a8ccebc1f8bb201f [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: a063ad9983a543b7a8ccebc1f8bb201f, State: Initialized, Role: FOLLOWER
I20260812 06:18:39.952891 27685 consensus_queue.cc:260] T 00000000000000000000000000000000 P a063ad9983a543b7a8ccebc1f8bb201f [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: "a063ad9983a543b7a8ccebc1f8bb201f" member_type: VOTER }
I20260812 06:18:39.953075 27685 raft_consensus.cc:399] T 00000000000000000000000000000000 P a063ad9983a543b7a8ccebc1f8bb201f [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:39.953145 27685 raft_consensus.cc:493] T 00000000000000000000000000000000 P a063ad9983a543b7a8ccebc1f8bb201f [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:39.953328 27685 raft_consensus.cc:3060] T 00000000000000000000000000000000 P a063ad9983a543b7a8ccebc1f8bb201f [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:39.954107 27685 raft_consensus.cc:515] T 00000000000000000000000000000000 P a063ad9983a543b7a8ccebc1f8bb201f [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a063ad9983a543b7a8ccebc1f8bb201f" member_type: VOTER }
I20260812 06:18:39.954537 27685 leader_election.cc:304] T 00000000000000000000000000000000 P a063ad9983a543b7a8ccebc1f8bb201f [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: a063ad9983a543b7a8ccebc1f8bb201f; no voters: 
I20260812 06:18:39.954854 27685 leader_election.cc:290] T 00000000000000000000000000000000 P a063ad9983a543b7a8ccebc1f8bb201f [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:39.954983 27688 raft_consensus.cc:2804] T 00000000000000000000000000000000 P a063ad9983a543b7a8ccebc1f8bb201f [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:39.955261 27688 raft_consensus.cc:697] T 00000000000000000000000000000000 P a063ad9983a543b7a8ccebc1f8bb201f [term 1 LEADER]: Becoming Leader. State: Replica: a063ad9983a543b7a8ccebc1f8bb201f, State: Running, Role: LEADER
I20260812 06:18:39.955670 27688 consensus_queue.cc:237] T 00000000000000000000000000000000 P a063ad9983a543b7a8ccebc1f8bb201f [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: "a063ad9983a543b7a8ccebc1f8bb201f" member_type: VOTER }
I20260812 06:18:39.955888 27685 sys_catalog.cc:565] T 00000000000000000000000000000000 P a063ad9983a543b7a8ccebc1f8bb201f [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:39.957615 27691 sys_catalog.cc:455] T 00000000000000000000000000000000 P a063ad9983a543b7a8ccebc1f8bb201f [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "a063ad9983a543b7a8ccebc1f8bb201f" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a063ad9983a543b7a8ccebc1f8bb201f" member_type: VOTER } }
I20260812 06:18:39.957789 27691 sys_catalog.cc:458] T 00000000000000000000000000000000 P a063ad9983a543b7a8ccebc1f8bb201f [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:39.957612 27692 sys_catalog.cc:455] T 00000000000000000000000000000000 P a063ad9983a543b7a8ccebc1f8bb201f [sys.catalog]: SysCatalogTable state changed. Reason: New leader a063ad9983a543b7a8ccebc1f8bb201f. Latest consensus state: current_term: 1 leader_uuid: "a063ad9983a543b7a8ccebc1f8bb201f" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a063ad9983a543b7a8ccebc1f8bb201f" member_type: VOTER } }
I20260812 06:18:39.958029 27692 sys_catalog.cc:458] T 00000000000000000000000000000000 P a063ad9983a543b7a8ccebc1f8bb201f [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:39.958176 27708 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:39.958271 27570 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:39.960546 27708 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:39.964921 27708 catalog_manager.cc:1383] Generated new cluster ID: aa748143739947dbab391a6060838dd7
I20260812 06:18:39.964983 27708 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:39.975060 27708 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:39.975857 27708 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:39.980099 27708 catalog_manager.cc:6092] T 00000000000000000000000000000000 P a063ad9983a543b7a8ccebc1f8bb201f: Generated new TSK 0
I20260812 06:18:39.980669 27708 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:39.990701 27570 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:39.993280 27721 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:39.993367 27720 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:39.993299 27725 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:39.993773 27570 server_base.cc:1061] running on GCE node
I20260812 06:18:39.993969 27570 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:39.994019 27570 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:39.994041 27570 hybrid_clock.cc:648] HybridClock initialized: now 1786515519994041 us; error 0 us; skew 500 ppm
I20260812 06:18:39.994989 27570 webserver.cc:533] Webserver started at http://127.26.236.129:38591/ using document root <none> and password file <none>
I20260812 06:18:39.995159 27570 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:39.995220 27570 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:39.995294 27570 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:39.995723 27570 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519867826-27570-0/minicluster-data/ts-0-root/instance:
uuid: "8a6edff151604015b96fe4d39767eb13"
format_stamp: "Formatted at 2026-08-12 06:18:39 on dist-test-slave-gmjp"
I20260812 06:18:39.997552 27570 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:18:39.998675 27736 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:39.998966 27570 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:39.999046 27570 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519867826-27570-0/minicluster-data/ts-0-root
uuid: "8a6edff151604015b96fe4d39767eb13"
format_stamp: "Formatted at 2026-08-12 06:18:39 on dist-test-slave-gmjp"
I20260812 06:18:39.999125 27570 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519867826-27570-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519867826-27570-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519867826-27570-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:40.018010 27570 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:40.018567 27570 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:40.019203 27570 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:40.020115 27570 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:40.020208 27570 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:40.020285 27570 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:40.020346 27570 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:40.027099 27570 rpc_server.cc:307] RPC server started. Bound to: 127.26.236.129:46785
I20260812 06:18:40.027132 27846 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.26.236.129:46785 every 8 connection(s)
I20260812 06:18:40.039614 27850 heartbeater.cc:344] Connected to a master server at 127.26.236.190:35231
I20260812 06:18:40.039885 27850 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:40.040432 27850 heartbeater.cc:507] Master 127.26.236.190:35231 requested a full tablet report, sending...
I20260812 06:18:40.041828 27625 ts_manager.cc:194] Registered new tserver with Master: 8a6edff151604015b96fe4d39767eb13 (127.26.236.129:46785)
I20260812 06:18:40.042162 27570 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.014413217s
I20260812 06:18:40.043368 27625 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:48354
I20260812 06:18:40.051416 27625 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:48362:
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:40.067008 27783 tablet_service.cc:1511] Processing CreateTablet for tablet 080054c342da46e981b0a1b81bb81c20 (DEFAULT_TABLE table=heavy-update-compaction-test [id=366f80854913437ebbf0d396630ba3cc]), partition=
I20260812 06:18:40.067476 27783 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 080054c342da46e981b0a1b81bb81c20. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:40.070176 27876 tablet_bootstrap.cc:492] T 080054c342da46e981b0a1b81bb81c20 P 8a6edff151604015b96fe4d39767eb13: Bootstrap starting.
I20260812 06:18:40.071045 27876 tablet_bootstrap.cc:654] T 080054c342da46e981b0a1b81bb81c20 P 8a6edff151604015b96fe4d39767eb13: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:40.072196 27876 tablet_bootstrap.cc:492] T 080054c342da46e981b0a1b81bb81c20 P 8a6edff151604015b96fe4d39767eb13: No bootstrap required, opened a new log
I20260812 06:18:40.072324 27876 ts_tablet_manager.cc:1403] T 080054c342da46e981b0a1b81bb81c20 P 8a6edff151604015b96fe4d39767eb13: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:40.072880 27876 raft_consensus.cc:359] T 080054c342da46e981b0a1b81bb81c20 P 8a6edff151604015b96fe4d39767eb13 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8a6edff151604015b96fe4d39767eb13" member_type: VOTER last_known_addr { host: "127.26.236.129" port: 46785 } }
I20260812 06:18:40.073001 27876 raft_consensus.cc:385] T 080054c342da46e981b0a1b81bb81c20 P 8a6edff151604015b96fe4d39767eb13 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:40.073082 27876 raft_consensus.cc:740] T 080054c342da46e981b0a1b81bb81c20 P 8a6edff151604015b96fe4d39767eb13 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 8a6edff151604015b96fe4d39767eb13, State: Initialized, Role: FOLLOWER
I20260812 06:18:40.073297 27876 consensus_queue.cc:260] T 080054c342da46e981b0a1b81bb81c20 P 8a6edff151604015b96fe4d39767eb13 [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: "8a6edff151604015b96fe4d39767eb13" member_type: VOTER last_known_addr { host: "127.26.236.129" port: 46785 } }
I20260812 06:18:40.073432 27876 raft_consensus.cc:399] T 080054c342da46e981b0a1b81bb81c20 P 8a6edff151604015b96fe4d39767eb13 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:40.073485 27876 raft_consensus.cc:493] T 080054c342da46e981b0a1b81bb81c20 P 8a6edff151604015b96fe4d39767eb13 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:40.073542 27876 raft_consensus.cc:3060] T 080054c342da46e981b0a1b81bb81c20 P 8a6edff151604015b96fe4d39767eb13 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:40.074237 27876 raft_consensus.cc:515] T 080054c342da46e981b0a1b81bb81c20 P 8a6edff151604015b96fe4d39767eb13 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8a6edff151604015b96fe4d39767eb13" member_type: VOTER last_known_addr { host: "127.26.236.129" port: 46785 } }
I20260812 06:18:40.074390 27876 leader_election.cc:304] T 080054c342da46e981b0a1b81bb81c20 P 8a6edff151604015b96fe4d39767eb13 [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: 8a6edff151604015b96fe4d39767eb13; no voters: 
I20260812 06:18:40.074610 27876 leader_election.cc:290] T 080054c342da46e981b0a1b81bb81c20 P 8a6edff151604015b96fe4d39767eb13 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:40.074751 27880 raft_consensus.cc:2804] T 080054c342da46e981b0a1b81bb81c20 P 8a6edff151604015b96fe4d39767eb13 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:40.074937 27876 ts_tablet_manager.cc:1434] T 080054c342da46e981b0a1b81bb81c20 P 8a6edff151604015b96fe4d39767eb13: Time spent starting tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:18:40.075181 27850 heartbeater.cc:499] Master 127.26.236.190:35231 was elected leader, sending a full tablet report...
I20260812 06:18:40.075512 27880 raft_consensus.cc:697] T 080054c342da46e981b0a1b81bb81c20 P 8a6edff151604015b96fe4d39767eb13 [term 1 LEADER]: Becoming Leader. State: Replica: 8a6edff151604015b96fe4d39767eb13, State: Running, Role: LEADER
I20260812 06:18:40.075692 27880 consensus_queue.cc:237] T 080054c342da46e981b0a1b81bb81c20 P 8a6edff151604015b96fe4d39767eb13 [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: "8a6edff151604015b96fe4d39767eb13" member_type: VOTER last_known_addr { host: "127.26.236.129" port: 46785 } }
I20260812 06:18:40.078410 27625 catalog_manager.cc:5719] T 080054c342da46e981b0a1b81bb81c20 P 8a6edff151604015b96fe4d39767eb13 reported cstate change: term changed from 0 to 1, leader changed from <none> to 8a6edff151604015b96fe4d39767eb13 (127.26.236.129). New cstate: current_term: 1 leader_uuid: "8a6edff151604015b96fe4d39767eb13" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8a6edff151604015b96fe4d39767eb13" member_type: VOTER last_known_addr { host: "127.26.236.129" port: 46785 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:40.142284 27570 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.055s	user 0.026s	sys 0.000s
I20260812 06:18:40.278195 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling FlushMRSOp(080054c342da46e981b0a1b81bb81c20): perf score=15.086190
I20260812 06:18:40.433846 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: FlushMRSOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.155s	user 0.125s	sys 0.024s Metrics: {"bytes_written":11897250,"cfile_init":1,"compiler_manager_pool.queue_time_us":229,"delete_count":0,"dirs.queue_time_us":44,"dirs.run_cpu_time_us":229,"dirs.run_wall_time_us":862,"drs_written":1,"lbm_read_time_us":71,"lbm_reads_lt_1ms":4,"lbm_write_time_us":38318,"lbm_writes_lt_1ms":657,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":94,"threads_started":1,"update_count":1450}
I20260812 06:18:40.435002 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling LogGCOp(080054c342da46e981b0a1b81bb81c20): free 20743880 bytes of WAL
I20260812 06:18:40.435341 27746 log_reader.cc:385] T 080054c342da46e981b0a1b81bb81c20: removed 2 log segments from log reader
I20260812 06:18:40.435412 27746 log.cc:1079] T 080054c342da46e981b0a1b81bb81c20 P 8a6edff151604015b96fe4d39767eb13: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/080054c342da46e981b0a1b81bb81c20/wal-000000001 (ops 1-6)
I20260812 06:18:40.435464 27746 log.cc:1079] T 080054c342da46e981b0a1b81bb81c20 P 8a6edff151604015b96fe4d39767eb13: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/080054c342da46e981b0a1b81bb81c20/wal-000000002 (ops 7-11)
I20260812 06:18:40.441152 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: LogGCOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.006s	user 0.000s	sys 0.005s Metrics: {}
I20260812 06:18:40.441567 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20): perf score=2.188937
I20260812 06:18:40.457623 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.016s	user 0.013s	sys 0.002s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5949,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:40.458134 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling MajorDeltaCompactionOp(080054c342da46e981b0a1b81bb81c20): perf score=1.000000
I20260812 06:18:40.591948 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: MajorDeltaCompactionOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.134s	user 0.097s	sys 0.036s Metrics: {"cfile_cache_miss":422,"cfile_cache_miss_bytes":20262037,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":914,"lbm_read_time_us":9324,"lbm_reads_lt_1ms":458,"lbm_write_time_us":24249,"lbm_writes_lt_1ms":433,"peak_mem_usage":49238594,"reinsert_count":0,"spinlock_wait_cycles":1664,"thread_start_us":338,"threads_started":5,"update_count":1950}
I20260812 06:18:40.592497 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling UndoDeltaBlockGCOp(080054c342da46e981b0a1b81bb81c20): 12719216 bytes on disk
I20260812 06:18:40.593209 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: UndoDeltaBlockGCOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":90,"lbm_reads_lt_1ms":4}
I20260812 06:18:40.593663 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20): perf score=10.126437
I20260812 06:18:40.633050 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.039s	user 0.018s	sys 0.019s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16119,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:40.633540 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20): perf score=2.188937
I20260812 06:18:40.643994 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3928,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:40.644598 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling MajorDeltaCompactionOp(080054c342da46e981b0a1b81bb81c20): perf score=1.000000
I20260812 06:18:40.766957 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: MajorDeltaCompactionOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.122s	user 0.098s	sys 0.024s 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":272,"lbm_read_time_us":7463,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25130,"lbm_writes_lt_1ms":443,"mutex_wait_us":29,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":23424,"update_count":2000}
I20260812 06:18:40.767567 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20): perf score=10.126437
I20260812 06:18:40.811182 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.043s	user 0.023s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13061,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:40.811671 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20): perf score=2.188937
I20260812 06:18:40.822413 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3959,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:40.823091 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling MajorDeltaCompactionOp(080054c342da46e981b0a1b81bb81c20): perf score=1.000000
I20260812 06:18:40.951179 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: MajorDeltaCompactionOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.128s	user 0.112s	sys 0.016s 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":250,"lbm_read_time_us":10016,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23577,"lbm_writes_lt_1ms":443,"mutex_wait_us":47,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11392,"update_count":2000}
I20260812 06:18:40.951712 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20): perf score=10.126437
I20260812 06:18:41.005627 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.054s	user 0.030s	sys 0.019s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":20505,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"mutex_wait_us":21,"reinsert_count":0,"update_count":1500}
I20260812 06:18:41.006112 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20): perf score=2.188937
I20260812 06:18:41.016481 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4056,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:41.016952 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling MajorDeltaCompactionOp(080054c342da46e981b0a1b81bb81c20): perf score=1.000000
I20260812 06:18:41.166545 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: MajorDeltaCompactionOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.149s	user 0.084s	sys 0.064s 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":835,"lbm_read_time_us":10428,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23825,"lbm_writes_lt_1ms":443,"mutex_wait_us":307,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":2000}
I20260812 06:18:41.167140 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20): perf score=10.126437
I20260812 06:18:41.213773 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.046s	user 0.023s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16820,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:41.214273 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20): perf score=2.188937
I20260812 06:18:41.225656 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4221,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:41.226125 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling MajorDeltaCompactionOp(080054c342da46e981b0a1b81bb81c20): perf score=1.000000
I20260812 06:18:41.354053 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: MajorDeltaCompactionOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.128s	user 0.100s	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":2056,"lbm_read_time_us":9339,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25661,"lbm_writes_lt_1ms":443,"mutex_wait_us":52,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5248,"update_count":2000}
I20260812 06:18:41.355608 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20): perf score=10.126437
I20260812 06:18:41.390249 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.034s	user 0.032s	sys 0.000s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15202,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:41.390703 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20): perf score=2.188937
I20260812 06:18:41.402390 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4468,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:41.402953 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling MajorDeltaCompactionOp(080054c342da46e981b0a1b81bb81c20): perf score=1.000000
I20260812 06:18:41.529057 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: MajorDeltaCompactionOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.126s	user 0.095s	sys 0.028s 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":4194,"lbm_read_time_us":8895,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22759,"lbm_writes_lt_1ms":443,"mutex_wait_us":3150,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9088,"update_count":2000}
I20260812 06:18:41.530200 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20): perf score=10.126437
I20260812 06:18:41.569032 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.038s	user 0.022s	sys 0.015s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":19980,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:41.569532 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20): perf score=2.188937
I20260812 06:18:41.581022 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4354,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:41.581466 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling MajorDeltaCompactionOp(080054c342da46e981b0a1b81bb81c20): perf score=1.000000
I20260812 06:18:41.706355 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: MajorDeltaCompactionOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.125s	user 0.112s	sys 0.012s 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":519,"lbm_read_time_us":7904,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24682,"lbm_writes_lt_1ms":443,"mutex_wait_us":316,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:18:41.708608 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20): perf score=10.126437
I20260812 06:18:41.762210 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.053s	user 0.024s	sys 0.024s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":18689,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:41.762758 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20): perf score=2.188937
I20260812 06:18:41.773113 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4130,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:41.773525 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling FlushMRSOp(080054c342da46e981b0a1b81bb81c20): perf score=1.000000
I20260812 06:18:41.818239 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: FlushMRSOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.045s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1275443,"cfile_init":1,"dirs.queue_time_us":52,"dirs.run_cpu_time_us":264,"dirs.run_wall_time_us":1195,"drs_written":1,"lbm_read_time_us":42,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1464,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:41.819141 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling LogGCOp(080054c342da46e981b0a1b81bb81c20): free 124257246 bytes of WAL
I20260812 06:18:41.819371 27746 log_reader.cc:385] T 080054c342da46e981b0a1b81bb81c20: removed 12 log segments from log reader
I20260812 06:18:41.819417 27746 log.cc:1079] T 080054c342da46e981b0a1b81bb81c20 P 8a6edff151604015b96fe4d39767eb13: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/080054c342da46e981b0a1b81bb81c20/wal-000000003 (ops 12-16)
I20260812 06:18:41.819446 27746 log.cc:1079] T 080054c342da46e981b0a1b81bb81c20 P 8a6edff151604015b96fe4d39767eb13: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/080054c342da46e981b0a1b81bb81c20/wal-000000004 (ops 17-21)
I20260812 06:18:41.819509 27746 log.cc:1079] T 080054c342da46e981b0a1b81bb81c20 P 8a6edff151604015b96fe4d39767eb13: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/080054c342da46e981b0a1b81bb81c20/wal-000000005 (ops 22-26)
I20260812 06:18:41.819553 27746 log.cc:1079] T 080054c342da46e981b0a1b81bb81c20 P 8a6edff151604015b96fe4d39767eb13: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/080054c342da46e981b0a1b81bb81c20/wal-000000006 (ops 27-30)
I20260812 06:18:41.819589 27746 log.cc:1079] T 080054c342da46e981b0a1b81bb81c20 P 8a6edff151604015b96fe4d39767eb13: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/080054c342da46e981b0a1b81bb81c20/wal-000000007 (ops 31-35)
I20260812 06:18:41.819646 27746 log.cc:1079] T 080054c342da46e981b0a1b81bb81c20 P 8a6edff151604015b96fe4d39767eb13: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/080054c342da46e981b0a1b81bb81c20/wal-000000008 (ops 36-40)
I20260812 06:18:41.819684 27746 log.cc:1079] T 080054c342da46e981b0a1b81bb81c20 P 8a6edff151604015b96fe4d39767eb13: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/080054c342da46e981b0a1b81bb81c20/wal-000000009 (ops 41-45)
I20260812 06:18:41.819725 27746 log.cc:1079] T 080054c342da46e981b0a1b81bb81c20 P 8a6edff151604015b96fe4d39767eb13: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/080054c342da46e981b0a1b81bb81c20/wal-000000010 (ops 46-50)
I20260812 06:18:41.819762 27746 log.cc:1079] T 080054c342da46e981b0a1b81bb81c20 P 8a6edff151604015b96fe4d39767eb13: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/080054c342da46e981b0a1b81bb81c20/wal-000000011 (ops 51-55)
I20260812 06:18:41.819800 27746 log.cc:1079] T 080054c342da46e981b0a1b81bb81c20 P 8a6edff151604015b96fe4d39767eb13: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/080054c342da46e981b0a1b81bb81c20/wal-000000012 (ops 56-60)
I20260812 06:18:41.819837 27746 log.cc:1079] T 080054c342da46e981b0a1b81bb81c20 P 8a6edff151604015b96fe4d39767eb13: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/080054c342da46e981b0a1b81bb81c20/wal-000000013 (ops 61-65)
I20260812 06:18:41.819875 27746 log.cc:1079] T 080054c342da46e981b0a1b81bb81c20 P 8a6edff151604015b96fe4d39767eb13: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/080054c342da46e981b0a1b81bb81c20/wal-000000014 (ops 66-70)
I20260812 06:18:41.848453 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: LogGCOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.029s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:18:41.848896 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20): perf score=3.181125
I20260812 06:18:41.867601 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.019s	user 0.010s	sys 0.006s Metrics: {"bytes_written":4512904,"delete_count":0,"lbm_write_time_us":6972,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:41.868043 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20): perf score=2.188937
I20260812 06:18:41.877609 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.009s	user 0.002s	sys 0.006s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3499,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:41.878113 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling UndoDeltaBlockGCOp(080054c342da46e981b0a1b81bb81c20): 481 bytes on disk
I20260812 06:18:41.878563 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: UndoDeltaBlockGCOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4}
I20260812 06:18:41.879011 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling MajorDeltaCompactionOp(080054c342da46e981b0a1b81bb81c20): perf score=1.000000
I20260812 06:18:42.076534 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: MajorDeltaCompactionOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.197s	user 0.141s	sys 0.056s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877329,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":861,"lbm_read_time_us":11493,"lbm_reads_lt_1ms":674,"lbm_write_time_us":33967,"lbm_writes_lt_1ms":643,"mutex_wait_us":278,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":6912,"thread_start_us":91,"threads_started":1,"update_count":3000}
I20260812 06:18:42.077340 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20): perf score=14.095187
I20260812 06:18:42.121896 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.044s	user 0.019s	sys 0.024s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":19450,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:42.122360 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling MajorDeltaCompactionOp(080054c342da46e981b0a1b81bb81c20): perf score=1.000000
I20260812 06:18:42.271633 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: MajorDeltaCompactionOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.149s	user 0.116s	sys 0.032s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672154,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":565,"lbm_read_time_us":9277,"lbm_reads_lt_1ms":467,"lbm_write_time_us":25665,"lbm_writes_lt_1ms":443,"mutex_wait_us":360,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":17024,"update_count":2000}
I20260812 06:18:42.272312 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20): perf score=10.126437
I20260812 06:18:42.313050 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.041s	user 0.019s	sys 0.020s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17740,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:42.313508 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20): perf score=2.188937
I20260812 06:18:42.325639 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4702,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:42.326082 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling MajorDeltaCompactionOp(080054c342da46e981b0a1b81bb81c20): perf score=1.000000
I20260812 06:18:42.464376 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: MajorDeltaCompactionOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.138s	user 0.109s	sys 0.027s 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":351,"lbm_read_time_us":9163,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26889,"lbm_writes_lt_1ms":443,"mutex_wait_us":1,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:42.468290 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20): perf score=10.126437
I20260812 06:18:42.509550 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.041s	user 0.027s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18211,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:42.510120 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20): perf score=2.188937
I20260812 06:18:42.523692 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.013s	user 0.007s	sys 0.003s 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:42.524398 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling MajorDeltaCompactionOp(080054c342da46e981b0a1b81bb81c20): perf score=1.000000
I20260812 06:18:42.664497 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: MajorDeltaCompactionOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.140s	user 0.111s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":96,"lbm_read_time_us":8794,"lbm_reads_lt_1ms":464,"lbm_write_time_us":29196,"lbm_writes_lt_1ms":443,"mutex_wait_us":25,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":23680,"update_count":2000}
I20260812 06:18:42.665606 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20): perf score=11.118625
I20260812 06:18:42.699354 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.033s	user 0.019s	sys 0.011s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":14975,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:42.699925 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20): perf score=2.188937
I20260812 06:18:42.714154 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5946,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":92,"reinsert_count":0,"update_count":450}
I20260812 06:18:42.714679 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling MajorDeltaCompactionOp(080054c342da46e981b0a1b81bb81c20): perf score=1.000000
I20260812 06:18:42.832772 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: MajorDeltaCompactionOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.118s	user 0.092s	sys 0.026s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672267,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1004,"lbm_read_time_us":7346,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24335,"lbm_writes_lt_1ms":443,"mutex_wait_us":314,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":2000}
I20260812 06:18:42.834358 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20): perf score=10.126437
I20260812 06:18:42.878561 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.044s	user 0.025s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15155,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:42.879220 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20): perf score=2.188937
I20260812 06:18:42.896215 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.017s	user 0.017s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6593,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:42.896941 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling MajorDeltaCompactionOp(080054c342da46e981b0a1b81bb81c20): perf score=1.000000
I20260812 06:18:43.032670 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: MajorDeltaCompactionOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.136s	user 0.088s	sys 0.048s 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":144,"lbm_read_time_us":10322,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23843,"lbm_writes_lt_1ms":443,"mutex_wait_us":22,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7936,"update_count":2000}
I20260812 06:18:43.033751 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20): perf score=11.118625
I20260812 06:18:43.071343 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.037s	user 0.017s	sys 0.017s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14995,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:43.071822 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20): perf score=2.188937
I20260812 06:18:43.094776 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.023s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5580,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:43.095290 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20): perf score=2.188937
I20260812 06:18:43.105752 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4034,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.106184 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling MajorDeltaCompactionOp(080054c342da46e981b0a1b81bb81c20): perf score=1.000000
I20260812 06:18:43.268270 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: MajorDeltaCompactionOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.162s	user 0.145s	sys 0.016s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774798,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1088,"lbm_read_time_us":10202,"lbm_reads_lt_1ms":573,"lbm_write_time_us":34376,"lbm_writes_lt_1ms":543,"mutex_wait_us":136,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":24832,"update_count":2500}
I20260812 06:18:43.269093 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20): perf score=10.126437
I20260812 06:18:43.311100 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.042s	user 0.036s	sys 0.002s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19006,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":1500}
I20260812 06:18:43.312080 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20): perf score=2.188937
I20260812 06:18:43.338842 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.026s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5805,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.339309 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20): perf score=2.188937
I20260812 06:18:43.349834 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3969,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.350289 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling FlushMRSOp(080054c342da46e981b0a1b81bb81c20): perf score=1.000000
I20260812 06:18:43.385378 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: FlushMRSOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.035s	user 0.029s	sys 0.004s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":65,"dirs.run_cpu_time_us":153,"dirs.run_wall_time_us":1073,"drs_written":1,"lbm_read_time_us":67,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2109,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:18:43.386191 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling LogGCOp(080054c342da46e981b0a1b81bb81c20): free 129773581 bytes of WAL
I20260812 06:18:43.386468 27746 log_reader.cc:385] T 080054c342da46e981b0a1b81bb81c20: removed 13 log segments from log reader
I20260812 06:18:43.386530 27746 log.cc:1079] T 080054c342da46e981b0a1b81bb81c20 P 8a6edff151604015b96fe4d39767eb13: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/080054c342da46e981b0a1b81bb81c20/wal-000000015 (ops 71-75)
I20260812 06:18:43.386567 27746 log.cc:1079] T 080054c342da46e981b0a1b81bb81c20 P 8a6edff151604015b96fe4d39767eb13: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/080054c342da46e981b0a1b81bb81c20/wal-000000016 (ops 76-80)
I20260812 06:18:43.386598 27746 log.cc:1079] T 080054c342da46e981b0a1b81bb81c20 P 8a6edff151604015b96fe4d39767eb13: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/080054c342da46e981b0a1b81bb81c20/wal-000000017 (ops 81-85)
I20260812 06:18:43.386628 27746 log.cc:1079] T 080054c342da46e981b0a1b81bb81c20 P 8a6edff151604015b96fe4d39767eb13: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/080054c342da46e981b0a1b81bb81c20/wal-000000018 (ops 86-90)
I20260812 06:18:43.386662 27746 log.cc:1079] T 080054c342da46e981b0a1b81bb81c20 P 8a6edff151604015b96fe4d39767eb13: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/080054c342da46e981b0a1b81bb81c20/wal-000000019 (ops 91-94)
I20260812 06:18:43.386696 27746 log.cc:1079] T 080054c342da46e981b0a1b81bb81c20 P 8a6edff151604015b96fe4d39767eb13: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/080054c342da46e981b0a1b81bb81c20/wal-000000020 (ops 95-99)
I20260812 06:18:43.386719 27746 log.cc:1079] T 080054c342da46e981b0a1b81bb81c20 P 8a6edff151604015b96fe4d39767eb13: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/080054c342da46e981b0a1b81bb81c20/wal-000000021 (ops 100-104)
I20260812 06:18:43.386742 27746 log.cc:1079] T 080054c342da46e981b0a1b81bb81c20 P 8a6edff151604015b96fe4d39767eb13: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/080054c342da46e981b0a1b81bb81c20/wal-000000022 (ops 105-109)
I20260812 06:18:43.386770 27746 log.cc:1079] T 080054c342da46e981b0a1b81bb81c20 P 8a6edff151604015b96fe4d39767eb13: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/080054c342da46e981b0a1b81bb81c20/wal-000000023 (ops 110-114)
I20260812 06:18:43.386801 27746 log.cc:1079] T 080054c342da46e981b0a1b81bb81c20 P 8a6edff151604015b96fe4d39767eb13: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/080054c342da46e981b0a1b81bb81c20/wal-000000024 (ops 115-119)
I20260812 06:18:43.386837 27746 log.cc:1079] T 080054c342da46e981b0a1b81bb81c20 P 8a6edff151604015b96fe4d39767eb13: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/080054c342da46e981b0a1b81bb81c20/wal-000000025 (ops 120-124)
I20260812 06:18:43.386873 27746 log.cc:1079] T 080054c342da46e981b0a1b81bb81c20 P 8a6edff151604015b96fe4d39767eb13: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/080054c342da46e981b0a1b81bb81c20/wal-000000026 (ops 125-129)
I20260812 06:18:43.386902 27746 log.cc:1079] T 080054c342da46e981b0a1b81bb81c20 P 8a6edff151604015b96fe4d39767eb13: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/080054c342da46e981b0a1b81bb81c20/wal-000000027 (ops 130-134)
I20260812 06:18:43.416038 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: LogGCOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.030s	user 0.003s	sys 0.023s Metrics: {}
I20260812 06:18:43.416852 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling UndoDeltaBlockGCOp(080054c342da46e981b0a1b81bb81c20): 493 bytes on disk
I20260812 06:18:43.417356 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: UndoDeltaBlockGCOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4}
I20260812 06:18:43.417923 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20): perf score=3.181125
I20260812 06:18:43.438865 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.021s	user 0.003s	sys 0.015s Metrics: {"bytes_written":5128263,"delete_count":0,"lbm_write_time_us":5151,"lbm_writes_lt_1ms":128,"reinsert_count":0,"update_count":625}
I20260812 06:18:43.439385 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling LogGCOp(080054c342da46e981b0a1b81bb81c20): free 11564893 bytes of WAL
I20260812 06:18:43.439601 27746 log_reader.cc:385] T 080054c342da46e981b0a1b81bb81c20: removed 1 log segments from log reader
I20260812 06:18:43.439644 27746 log.cc:1079] T 080054c342da46e981b0a1b81bb81c20 P 8a6edff151604015b96fe4d39767eb13: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/080054c342da46e981b0a1b81bb81c20/wal-000000028 (ops 135-138)
I20260812 06:18:43.441962 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: LogGCOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.002s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:18:43.442241 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20): perf score=1.196750
I20260812 06:18:43.453728 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.011s	user 0.008s	sys 0.001s Metrics: {"bytes_written":3077030,"delete_count":0,"lbm_write_time_us":3258,"lbm_writes_lt_1ms":78,"reinsert_count":0,"update_count":375}
I20260812 06:18:43.456029 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling MajorDeltaCompactionOp(080054c342da46e981b0a1b81bb81c20): perf score=1.000000
I20260812 06:18:43.714887 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: MajorDeltaCompactionOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.259s	user 0.156s	sys 0.097s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979845,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":496,"lbm_read_time_us":18844,"lbm_reads_lt_1ms":775,"lbm_write_time_us":44991,"lbm_writes_lt_1ms":743,"mutex_wait_us":20,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":15488,"thread_start_us":84,"threads_started":1,"update_count":3500}
I20260812 06:18:43.716569 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20): perf score=11.118625
I20260812 06:18:43.761577 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.045s	user 0.013s	sys 0.030s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14246,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:43.762212 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20): perf score=2.188937
I20260812 06:18:43.774750 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4830,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:43.775192 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling MajorDeltaCompactionOp(080054c342da46e981b0a1b81bb81c20): perf score=1.000000
I20260812 06:18:43.960505 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: MajorDeltaCompactionOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.185s	user 0.122s	sys 0.053s 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":530,"lbm_read_time_us":11200,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29346,"lbm_writes_lt_1ms":443,"mutex_wait_us":20,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9344,"update_count":2000}
I20260812 06:18:43.961160 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20): perf score=10.126437
I20260812 06:18:44.001263 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.040s	user 0.020s	sys 0.013s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":14303,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:44.001760 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20): perf score=2.188937
I20260812 06:18:44.012116 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4012,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.012778 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling MajorDeltaCompactionOp(080054c342da46e981b0a1b81bb81c20): perf score=1.000000
I20260812 06:18:44.139043 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: MajorDeltaCompactionOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.125s	user 0.103s	sys 0.022s 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":268,"lbm_read_time_us":9781,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22352,"lbm_writes_lt_1ms":443,"mutex_wait_us":22,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10624,"update_count":2000}
I20260812 06:18:44.139652 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20): perf score=10.126437
I20260812 06:18:44.181691 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.042s	user 0.028s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16804,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:44.182281 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20): perf score=2.188937
I20260812 06:18:44.193602 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3886,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.194069 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling MajorDeltaCompactionOp(080054c342da46e981b0a1b81bb81c20): perf score=1.000000
I20260812 06:18:44.319247 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: MajorDeltaCompactionOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.125s	user 0.117s	sys 0.008s 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":297,"lbm_read_time_us":10243,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23251,"lbm_writes_lt_1ms":443,"mutex_wait_us":34,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":2000}
I20260812 06:18:44.319870 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20): perf score=10.126437
I20260812 06:18:44.377125 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.057s	user 0.025s	sys 0.031s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":20218,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:44.377795 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20): perf score=2.188937
I20260812 06:18:44.395612 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.018s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6682,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.396317 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling MajorDeltaCompactionOp(080054c342da46e981b0a1b81bb81c20): perf score=1.000000
I20260812 06:18:44.543007 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: MajorDeltaCompactionOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.146s	user 0.101s	sys 0.045s 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":609,"lbm_read_time_us":10687,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25918,"lbm_writes_lt_1ms":443,"mutex_wait_us":22,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6144,"update_count":2000}
I20260812 06:18:44.543676 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20): perf score=10.126437
I20260812 06:18:44.585645 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.042s	user 0.021s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15224,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:44.586306 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20): perf score=2.188937
I20260812 06:18:44.598944 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5460,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":102,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.599392 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling MajorDeltaCompactionOp(080054c342da46e981b0a1b81bb81c20): perf score=1.000000
I20260812 06:18:44.723699 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: MajorDeltaCompactionOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.124s	user 0.090s	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":152,"lbm_read_time_us":8533,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24776,"lbm_writes_lt_1ms":443,"mutex_wait_us":39,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:18:44.724449 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20): perf score=10.126437
I20260812 06:18:44.757715 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.033s	user 0.030s	sys 0.000s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13838,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:44.758327 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling MajorDeltaCompactionOp(080054c342da46e981b0a1b81bb81c20): perf score=1.000000
I20260812 06:18:44.865324 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: MajorDeltaCompactionOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.107s	user 0.079s	sys 0.028s 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":294,"lbm_read_time_us":5769,"lbm_reads_lt_1ms":363,"lbm_write_time_us":20100,"lbm_writes_lt_1ms":343,"mutex_wait_us":35,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":29312,"update_count":1500}
I20260812 06:18:44.865932 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20): perf score=10.126437
I20260812 06:18:44.906520 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.040s	user 0.028s	sys 0.003s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14545,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":1500}
I20260812 06:18:44.906996 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20): perf score=2.188937
I20260812 06:18:44.917547 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3947,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.918377 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling FlushMRSOp(080054c342da46e981b0a1b81bb81c20): perf score=1.000000
I20260812 06:18:44.950345 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: FlushMRSOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.032s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1193507,"cfile_init":1,"dirs.queue_time_us":64,"dirs.run_cpu_time_us":225,"dirs.run_wall_time_us":1104,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1715,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:44.951007 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling LogGCOp(080054c342da46e981b0a1b81bb81c20): free 108535690 bytes of WAL
I20260812 06:18:44.951234 27746 log_reader.cc:385] T 080054c342da46e981b0a1b81bb81c20: removed 11 log segments from log reader
I20260812 06:18:44.951278 27746 log.cc:1079] T 080054c342da46e981b0a1b81bb81c20 P 8a6edff151604015b96fe4d39767eb13: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/080054c342da46e981b0a1b81bb81c20/wal-000000029 (ops 139-143)
I20260812 06:18:44.951306 27746 log.cc:1079] T 080054c342da46e981b0a1b81bb81c20 P 8a6edff151604015b96fe4d39767eb13: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/080054c342da46e981b0a1b81bb81c20/wal-000000030 (ops 144-148)
I20260812 06:18:44.951375 27746 log.cc:1079] T 080054c342da46e981b0a1b81bb81c20 P 8a6edff151604015b96fe4d39767eb13: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/080054c342da46e981b0a1b81bb81c20/wal-000000031 (ops 149-153)
I20260812 06:18:44.951417 27746 log.cc:1079] T 080054c342da46e981b0a1b81bb81c20 P 8a6edff151604015b96fe4d39767eb13: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/080054c342da46e981b0a1b81bb81c20/wal-000000032 (ops 154-158)
I20260812 06:18:44.951464 27746 log.cc:1079] T 080054c342da46e981b0a1b81bb81c20 P 8a6edff151604015b96fe4d39767eb13: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/080054c342da46e981b0a1b81bb81c20/wal-000000033 (ops 159-162)
I20260812 06:18:44.951519 27746 log.cc:1079] T 080054c342da46e981b0a1b81bb81c20 P 8a6edff151604015b96fe4d39767eb13: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/080054c342da46e981b0a1b81bb81c20/wal-000000034 (ops 163-167)
I20260812 06:18:44.951557 27746 log.cc:1079] T 080054c342da46e981b0a1b81bb81c20 P 8a6edff151604015b96fe4d39767eb13: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/080054c342da46e981b0a1b81bb81c20/wal-000000035 (ops 168-172)
I20260812 06:18:44.951601 27746 log.cc:1079] T 080054c342da46e981b0a1b81bb81c20 P 8a6edff151604015b96fe4d39767eb13: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/080054c342da46e981b0a1b81bb81c20/wal-000000036 (ops 173-176)
I20260812 06:18:44.951637 27746 log.cc:1079] T 080054c342da46e981b0a1b81bb81c20 P 8a6edff151604015b96fe4d39767eb13: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/080054c342da46e981b0a1b81bb81c20/wal-000000037 (ops 177-181)
I20260812 06:18:44.951675 27746 log.cc:1079] T 080054c342da46e981b0a1b81bb81c20 P 8a6edff151604015b96fe4d39767eb13: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/080054c342da46e981b0a1b81bb81c20/wal-000000038 (ops 182-186)
I20260812 06:18:44.951715 27746 log.cc:1079] T 080054c342da46e981b0a1b81bb81c20 P 8a6edff151604015b96fe4d39767eb13: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/080054c342da46e981b0a1b81bb81c20/wal-000000039 (ops 187-191)
I20260812 06:18:44.973929 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: LogGCOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.023s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:18:44.976955 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20): perf score=2.188937
I20260812 06:18:44.999378 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.022s	user 0.009s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6549,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.999902 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling UndoDeltaBlockGCOp(080054c342da46e981b0a1b81bb81c20): 462 bytes on disk
I20260812 06:18:45.000375 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: UndoDeltaBlockGCOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":88,"lbm_reads_lt_1ms":4}
I20260812 06:18:45.000923 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20): perf score=2.188937
I20260812 06:18:45.015558 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.014s	user 0.009s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5833,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.016127 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling MajorDeltaCompactionOp(080054c342da46e981b0a1b81bb81c20): perf score=1.000000
I20260812 06:18:45.112437 27570 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.970s	user 1.852s	sys 0.156s
I20260812 06:18:45.200400 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: MajorDeltaCompactionOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.184s	user 0.123s	sys 0.061s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877338,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":479,"lbm_read_time_us":12993,"lbm_reads_lt_1ms":670,"lbm_write_time_us":32494,"lbm_writes_lt_1ms":643,"mutex_wait_us":21,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":12544,"thread_start_us":82,"threads_started":1,"update_count":3000}
I20260812 06:18:45.201448 27851 maintenance_manager.cc:419] P 8a6edff151604015b96fe4d39767eb13: Scheduling FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20): perf score=6.157687
I20260812 06:18:45.205389 27570 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.092s	user 0.004s	sys 0.000s
I20260812 06:18:45.205982 27570 tablet_server.cc:179] TabletServer@127.26.236.129:0 shutting down...
I20260812 06:18:45.228117 27746 maintenance_manager.cc:643] P 8a6edff151604015b96fe4d39767eb13: FlushDeltaMemStoresOp(080054c342da46e981b0a1b81bb81c20) complete. Timing: real 0.026s	user 0.007s	sys 0.016s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":10246,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:18:45.228780 27570 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:45.229264 27570 tablet_replica.cc:333] T 080054c342da46e981b0a1b81bb81c20 P 8a6edff151604015b96fe4d39767eb13: stopping tablet replica
I20260812 06:18:45.229502 27570 raft_consensus.cc:2243] T 080054c342da46e981b0a1b81bb81c20 P 8a6edff151604015b96fe4d39767eb13 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:45.229753 27570 raft_consensus.cc:2272] T 080054c342da46e981b0a1b81bb81c20 P 8a6edff151604015b96fe4d39767eb13 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:45.248667 27570 tablet_server.cc:196] TabletServer@127.26.236.129:0 shutdown complete.
I20260812 06:18:45.253396 27570 master.cc:562] Master@127.26.236.190:35231 shutting down...
I20260812 06:18:45.257781 27570 raft_consensus.cc:2243] T 00000000000000000000000000000000 P a063ad9983a543b7a8ccebc1f8bb201f [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:45.257978 27570 raft_consensus.cc:2272] T 00000000000000000000000000000000 P a063ad9983a543b7a8ccebc1f8bb201f [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:45.258042 27570 tablet_replica.cc:333] T 00000000000000000000000000000000 P a063ad9983a543b7a8ccebc1f8bb201f: stopping tablet replica
I20260812 06:18:45.270406 27570 master.cc:584] Master@127.26.236.190:35231 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5481 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:45.371090 27570 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.26.236.190:42971
I20260812 06:18:45.371498 27570 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:45.373838 27908 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:45.373986 27570 server_base.cc:1061] running on GCE node
W20260812 06:18:45.374073 27909 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:45.374200 27912 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:45.374431 27570 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:45.374511 27570 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:45.374544 27570 hybrid_clock.cc:648] HybridClock initialized: now 1786515525374544 us; error 0 us; skew 500 ppm
I20260812 06:18:45.375784 27570 webserver.cc:533] Webserver started at http://127.26.236.190:39521/ using document root <none> and password file <none>
I20260812 06:18:45.376071 27570 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:45.376135 27570 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:45.376425 27570 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:45.376866 27570 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519867826-27570-0/minicluster-data/master-0-root/instance:
uuid: "051eeab9a01d499599578ce4656e568b"
format_stamp: "Formatted at 2026-08-12 06:18:45 on dist-test-slave-gmjp"
I20260812 06:18:45.378408 27570 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:45.379317 27922 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:45.379616 27570 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:45.379698 27570 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519867826-27570-0/minicluster-data/master-0-root
uuid: "051eeab9a01d499599578ce4656e568b"
format_stamp: "Formatted at 2026-08-12 06:18:45 on dist-test-slave-gmjp"
I20260812 06:18:45.379810 27570 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519867826-27570-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519867826-27570-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519867826-27570-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:45.397249 27570 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:45.397666 27570 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:45.402169 27570 rpc_server.cc:307] RPC server started. Bound to: 127.26.236.190:42971
I20260812 06:18:45.403097 28027 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.26.236.190:42971 every 8 connection(s)
I20260812 06:18:45.404480 28028 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:45.407291 28028 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 051eeab9a01d499599578ce4656e568b: Bootstrap starting.
I20260812 06:18:45.408047 28028 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 051eeab9a01d499599578ce4656e568b: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:45.409088 28028 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 051eeab9a01d499599578ce4656e568b: No bootstrap required, opened a new log
I20260812 06:18:45.409485 28028 raft_consensus.cc:359] T 00000000000000000000000000000000 P 051eeab9a01d499599578ce4656e568b [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "051eeab9a01d499599578ce4656e568b" member_type: VOTER }
I20260812 06:18:45.409592 28028 raft_consensus.cc:385] T 00000000000000000000000000000000 P 051eeab9a01d499599578ce4656e568b [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:45.409641 28028 raft_consensus.cc:740] T 00000000000000000000000000000000 P 051eeab9a01d499599578ce4656e568b [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 051eeab9a01d499599578ce4656e568b, State: Initialized, Role: FOLLOWER
I20260812 06:18:45.409817 28028 consensus_queue.cc:260] T 00000000000000000000000000000000 P 051eeab9a01d499599578ce4656e568b [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: "051eeab9a01d499599578ce4656e568b" member_type: VOTER }
I20260812 06:18:45.409926 28028 raft_consensus.cc:399] T 00000000000000000000000000000000 P 051eeab9a01d499599578ce4656e568b [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:45.409974 28028 raft_consensus.cc:493] T 00000000000000000000000000000000 P 051eeab9a01d499599578ce4656e568b [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:45.410032 28028 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 051eeab9a01d499599578ce4656e568b [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:45.410684 28028 raft_consensus.cc:515] T 00000000000000000000000000000000 P 051eeab9a01d499599578ce4656e568b [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "051eeab9a01d499599578ce4656e568b" member_type: VOTER }
I20260812 06:18:45.410827 28028 leader_election.cc:304] T 00000000000000000000000000000000 P 051eeab9a01d499599578ce4656e568b [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: 051eeab9a01d499599578ce4656e568b; no voters: 
I20260812 06:18:45.411016 28028 leader_election.cc:290] T 00000000000000000000000000000000 P 051eeab9a01d499599578ce4656e568b [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:45.411130 28034 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 051eeab9a01d499599578ce4656e568b [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:45.411365 28034 raft_consensus.cc:697] T 00000000000000000000000000000000 P 051eeab9a01d499599578ce4656e568b [term 1 LEADER]: Becoming Leader. State: Replica: 051eeab9a01d499599578ce4656e568b, State: Running, Role: LEADER
I20260812 06:18:45.411460 28028 sys_catalog.cc:565] T 00000000000000000000000000000000 P 051eeab9a01d499599578ce4656e568b [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:45.411521 28034 consensus_queue.cc:237] T 00000000000000000000000000000000 P 051eeab9a01d499599578ce4656e568b [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: "051eeab9a01d499599578ce4656e568b" member_type: VOTER }
I20260812 06:18:45.411996 28035 sys_catalog.cc:455] T 00000000000000000000000000000000 P 051eeab9a01d499599578ce4656e568b [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "051eeab9a01d499599578ce4656e568b" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "051eeab9a01d499599578ce4656e568b" member_type: VOTER } }
I20260812 06:18:45.412019 28037 sys_catalog.cc:455] T 00000000000000000000000000000000 P 051eeab9a01d499599578ce4656e568b [sys.catalog]: SysCatalogTable state changed. Reason: New leader 051eeab9a01d499599578ce4656e568b. Latest consensus state: current_term: 1 leader_uuid: "051eeab9a01d499599578ce4656e568b" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "051eeab9a01d499599578ce4656e568b" member_type: VOTER } }
I20260812 06:18:45.412094 28035 sys_catalog.cc:458] T 00000000000000000000000000000000 P 051eeab9a01d499599578ce4656e568b [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:45.412106 28037 sys_catalog.cc:458] T 00000000000000000000000000000000 P 051eeab9a01d499599578ce4656e568b [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:45.412369 28043 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:45.413166 28043 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:45.413359 27570 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:45.414964 28043 catalog_manager.cc:1383] Generated new cluster ID: fd804516edd04da791aef4c339ecad55
I20260812 06:18:45.415025 28043 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:45.437796 28043 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:45.438427 28043 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:45.449482 28043 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 051eeab9a01d499599578ce4656e568b: Generated new TSK 0
I20260812 06:18:45.449677 28043 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:45.478070 27570 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:45.480185 28069 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:45.480127 28064 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:45.480159 28066 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:45.480388 27570 server_base.cc:1061] running on GCE node
I20260812 06:18:45.480662 27570 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:45.480710 27570 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:45.480726 27570 hybrid_clock.cc:648] HybridClock initialized: now 1786515525480725 us; error 0 us; skew 500 ppm
I20260812 06:18:45.481657 27570 webserver.cc:533] Webserver started at http://127.26.236.129:35981/ using document root <none> and password file <none>
I20260812 06:18:45.481842 27570 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:45.481890 27570 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:45.481997 27570 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:45.482401 27570 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519867826-27570-0/minicluster-data/ts-0-root/instance:
uuid: "7a7ad99eae7d4cfe85fc871e66edf2b7"
format_stamp: "Formatted at 2026-08-12 06:18:45 on dist-test-slave-gmjp"
I20260812 06:18:45.483879 27570 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:45.484858 28079 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:45.485127 27570 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:45.485190 27570 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519867826-27570-0/minicluster-data/ts-0-root
uuid: "7a7ad99eae7d4cfe85fc871e66edf2b7"
format_stamp: "Formatted at 2026-08-12 06:18:45 on dist-test-slave-gmjp"
I20260812 06:18:45.485283 27570 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519867826-27570-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519867826-27570-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519867826-27570-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:45.503577 27570 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:45.503943 27570 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:45.504321 27570 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:45.504806 27570 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:45.504845 27570 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:45.504904 27570 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:45.504946 27570 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:45.509135 27570 rpc_server.cc:307] RPC server started. Bound to: 127.26.236.129:41181
I20260812 06:18:45.510710 28202 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.26.236.129:41181 every 8 connection(s)
I20260812 06:18:45.519449 28207 heartbeater.cc:344] Connected to a master server at 127.26.236.190:42971
I20260812 06:18:45.519572 28207 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:45.519840 28207 heartbeater.cc:507] Master 127.26.236.190:42971 requested a full tablet report, sending...
I20260812 06:18:45.520534 27957 ts_manager.cc:194] Registered new tserver with Master: 7a7ad99eae7d4cfe85fc871e66edf2b7 (127.26.236.129:41181)
I20260812 06:18:45.520964 27570 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011043372s
I20260812 06:18:45.521311 27957 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:52566
I20260812 06:18:45.527889 27957 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:52572:
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:45.536643 28140 tablet_service.cc:1511] Processing CreateTablet for tablet 86fc1a8e5ba14a46a1705b7cd5fd27ba (DEFAULT_TABLE table=heavy-update-compaction-test [id=053e17cb690f4b8487b72f1b3f5442f0]), partition=
I20260812 06:18:45.536933 28140 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 86fc1a8e5ba14a46a1705b7cd5fd27ba. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:45.539059 28230 tablet_bootstrap.cc:492] T 86fc1a8e5ba14a46a1705b7cd5fd27ba P 7a7ad99eae7d4cfe85fc871e66edf2b7: Bootstrap starting.
I20260812 06:18:45.539971 28230 tablet_bootstrap.cc:654] T 86fc1a8e5ba14a46a1705b7cd5fd27ba P 7a7ad99eae7d4cfe85fc871e66edf2b7: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:45.541074 28230 tablet_bootstrap.cc:492] T 86fc1a8e5ba14a46a1705b7cd5fd27ba P 7a7ad99eae7d4cfe85fc871e66edf2b7: No bootstrap required, opened a new log
I20260812 06:18:45.541147 28230 ts_tablet_manager.cc:1403] T 86fc1a8e5ba14a46a1705b7cd5fd27ba P 7a7ad99eae7d4cfe85fc871e66edf2b7: Time spent bootstrapping tablet: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:18:45.541602 28230 raft_consensus.cc:359] T 86fc1a8e5ba14a46a1705b7cd5fd27ba P 7a7ad99eae7d4cfe85fc871e66edf2b7 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7a7ad99eae7d4cfe85fc871e66edf2b7" member_type: VOTER last_known_addr { host: "127.26.236.129" port: 41181 } }
I20260812 06:18:45.541739 28230 raft_consensus.cc:385] T 86fc1a8e5ba14a46a1705b7cd5fd27ba P 7a7ad99eae7d4cfe85fc871e66edf2b7 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:45.541793 28230 raft_consensus.cc:740] T 86fc1a8e5ba14a46a1705b7cd5fd27ba P 7a7ad99eae7d4cfe85fc871e66edf2b7 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 7a7ad99eae7d4cfe85fc871e66edf2b7, State: Initialized, Role: FOLLOWER
I20260812 06:18:45.541939 28230 consensus_queue.cc:260] T 86fc1a8e5ba14a46a1705b7cd5fd27ba P 7a7ad99eae7d4cfe85fc871e66edf2b7 [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: "7a7ad99eae7d4cfe85fc871e66edf2b7" member_type: VOTER last_known_addr { host: "127.26.236.129" port: 41181 } }
I20260812 06:18:45.542069 28230 raft_consensus.cc:399] T 86fc1a8e5ba14a46a1705b7cd5fd27ba P 7a7ad99eae7d4cfe85fc871e66edf2b7 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:45.542128 28230 raft_consensus.cc:493] T 86fc1a8e5ba14a46a1705b7cd5fd27ba P 7a7ad99eae7d4cfe85fc871e66edf2b7 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:45.542188 28230 raft_consensus.cc:3060] T 86fc1a8e5ba14a46a1705b7cd5fd27ba P 7a7ad99eae7d4cfe85fc871e66edf2b7 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:45.542956 28230 raft_consensus.cc:515] T 86fc1a8e5ba14a46a1705b7cd5fd27ba P 7a7ad99eae7d4cfe85fc871e66edf2b7 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7a7ad99eae7d4cfe85fc871e66edf2b7" member_type: VOTER last_known_addr { host: "127.26.236.129" port: 41181 } }
I20260812 06:18:45.543116 28230 leader_election.cc:304] T 86fc1a8e5ba14a46a1705b7cd5fd27ba P 7a7ad99eae7d4cfe85fc871e66edf2b7 [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: 7a7ad99eae7d4cfe85fc871e66edf2b7; no voters: 
I20260812 06:18:45.543316 28230 leader_election.cc:290] T 86fc1a8e5ba14a46a1705b7cd5fd27ba P 7a7ad99eae7d4cfe85fc871e66edf2b7 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:45.543423 28236 raft_consensus.cc:2804] T 86fc1a8e5ba14a46a1705b7cd5fd27ba P 7a7ad99eae7d4cfe85fc871e66edf2b7 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:45.543670 28230 ts_tablet_manager.cc:1434] T 86fc1a8e5ba14a46a1705b7cd5fd27ba P 7a7ad99eae7d4cfe85fc871e66edf2b7: Time spent starting tablet: real 0.002s	user 0.000s	sys 0.003s
I20260812 06:18:45.543699 28207 heartbeater.cc:499] Master 127.26.236.190:42971 was elected leader, sending a full tablet report...
I20260812 06:18:45.543702 28236 raft_consensus.cc:697] T 86fc1a8e5ba14a46a1705b7cd5fd27ba P 7a7ad99eae7d4cfe85fc871e66edf2b7 [term 1 LEADER]: Becoming Leader. State: Replica: 7a7ad99eae7d4cfe85fc871e66edf2b7, State: Running, Role: LEADER
I20260812 06:18:45.543910 28236 consensus_queue.cc:237] T 86fc1a8e5ba14a46a1705b7cd5fd27ba P 7a7ad99eae7d4cfe85fc871e66edf2b7 [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: "7a7ad99eae7d4cfe85fc871e66edf2b7" member_type: VOTER last_known_addr { host: "127.26.236.129" port: 41181 } }
I20260812 06:18:45.545210 27957 catalog_manager.cc:5719] T 86fc1a8e5ba14a46a1705b7cd5fd27ba P 7a7ad99eae7d4cfe85fc871e66edf2b7 reported cstate change: term changed from 0 to 1, leader changed from <none> to 7a7ad99eae7d4cfe85fc871e66edf2b7 (127.26.236.129). New cstate: current_term: 1 leader_uuid: "7a7ad99eae7d4cfe85fc871e66edf2b7" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7a7ad99eae7d4cfe85fc871e66edf2b7" member_type: VOTER last_known_addr { host: "127.26.236.129" port: 41181 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:45.602308 27570 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.051s	user 0.014s	sys 0.008s
I20260812 06:18:45.761086 28208 maintenance_manager.cc:419] P 7a7ad99eae7d4cfe85fc871e66edf2b7: Scheduling FlushMRSOp(86fc1a8e5ba14a46a1705b7cd5fd27ba): perf score=21.039315
I20260812 06:18:45.920915 28092 maintenance_manager.cc:643] P 7a7ad99eae7d4cfe85fc871e66edf2b7: FlushMRSOp(86fc1a8e5ba14a46a1705b7cd5fd27ba) complete. Timing: real 0.160s	user 0.122s	sys 0.036s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":66,"dirs.run_cpu_time_us":208,"dirs.run_wall_time_us":711,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":40952,"lbm_writes_lt_1ms":857,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"update_count":1500}
I20260812 06:18:45.921639 28208 maintenance_manager.cc:419] P 7a7ad99eae7d4cfe85fc871e66edf2b7: Scheduling LogGCOp(86fc1a8e5ba14a46a1705b7cd5fd27ba): free 20290830 bytes of WAL
I20260812 06:18:45.921931 28092 log_reader.cc:385] T 86fc1a8e5ba14a46a1705b7cd5fd27ba: removed 2 log segments from log reader
I20260812 06:18:45.922006 28092 log.cc:1079] T 86fc1a8e5ba14a46a1705b7cd5fd27ba P 7a7ad99eae7d4cfe85fc871e66edf2b7: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/86fc1a8e5ba14a46a1705b7cd5fd27ba/wal-000000001 (ops 1-6)
I20260812 06:18:45.922053 28092 log.cc:1079] T 86fc1a8e5ba14a46a1705b7cd5fd27ba P 7a7ad99eae7d4cfe85fc871e66edf2b7: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/86fc1a8e5ba14a46a1705b7cd5fd27ba/wal-000000002 (ops 7-10)
I20260812 06:18:45.928140 28092 maintenance_manager.cc:643] P 7a7ad99eae7d4cfe85fc871e66edf2b7: LogGCOp(86fc1a8e5ba14a46a1705b7cd5fd27ba) complete. Timing: real 0.006s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:18:45.928561 28208 maintenance_manager.cc:419] P 7a7ad99eae7d4cfe85fc871e66edf2b7: Scheduling FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba): perf score=2.188937
I20260812 06:18:45.943181 28092 maintenance_manager.cc:643] P 7a7ad99eae7d4cfe85fc871e66edf2b7: FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba) complete. Timing: real 0.014s	user 0.003s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5157,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.943624 28208 maintenance_manager.cc:419] P 7a7ad99eae7d4cfe85fc871e66edf2b7: Scheduling UndoDeltaBlockGCOp(86fc1a8e5ba14a46a1705b7cd5fd27ba): 20513814 bytes on disk
I20260812 06:18:45.944144 28092 maintenance_manager.cc:643] P 7a7ad99eae7d4cfe85fc871e66edf2b7: UndoDeltaBlockGCOp(86fc1a8e5ba14a46a1705b7cd5fd27ba) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":82,"lbm_reads_lt_1ms":4}
I20260812 06:18:45.944621 28208 maintenance_manager.cc:419] P 7a7ad99eae7d4cfe85fc871e66edf2b7: Scheduling MajorDeltaCompactionOp(86fc1a8e5ba14a46a1705b7cd5fd27ba): perf score=1.000000
I20260812 06:18:46.101320 28092 maintenance_manager.cc:643] P 7a7ad99eae7d4cfe85fc871e66edf2b7: MajorDeltaCompactionOp(86fc1a8e5ba14a46a1705b7cd5fd27ba) complete. Timing: real 0.157s	user 0.101s	sys 0.044s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":485,"lbm_read_time_us":9532,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25678,"lbm_writes_lt_1ms":443,"mutex_wait_us":35,"peak_mem_usage":50689328,"reinsert_count":0,"thread_start_us":336,"threads_started":5,"update_count":2000}
I20260812 06:18:46.101845 28208 maintenance_manager.cc:419] P 7a7ad99eae7d4cfe85fc871e66edf2b7: Scheduling FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba): perf score=14.095187
I20260812 06:18:46.150928 28092 maintenance_manager.cc:643] P 7a7ad99eae7d4cfe85fc871e66edf2b7: FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba) complete. Timing: real 0.049s	user 0.036s	sys 0.009s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21300,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:46.151467 28208 maintenance_manager.cc:419] P 7a7ad99eae7d4cfe85fc871e66edf2b7: Scheduling MajorDeltaCompactionOp(86fc1a8e5ba14a46a1705b7cd5fd27ba): perf score=1.000000
I20260812 06:18:46.312865 28092 maintenance_manager.cc:643] P 7a7ad99eae7d4cfe85fc871e66edf2b7: MajorDeltaCompactionOp(86fc1a8e5ba14a46a1705b7cd5fd27ba) complete. Timing: real 0.161s	user 0.091s	sys 0.060s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713154,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":199,"lbm_read_time_us":11206,"lbm_reads_lt_1ms":463,"lbm_write_time_us":25158,"lbm_writes_lt_1ms":443,"mutex_wait_us":42,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":25856,"update_count":2000}
I20260812 06:18:46.313560 28208 maintenance_manager.cc:419] P 7a7ad99eae7d4cfe85fc871e66edf2b7: Scheduling FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba): perf score=14.095187
I20260812 06:18:46.362432 28092 maintenance_manager.cc:643] P 7a7ad99eae7d4cfe85fc871e66edf2b7: FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba) complete. Timing: real 0.049s	user 0.021s	sys 0.019s Metrics: {"bytes_written":16409899,"delete_count":0,"lbm_write_time_us":19046,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:46.362876 28208 maintenance_manager.cc:419] P 7a7ad99eae7d4cfe85fc871e66edf2b7: Scheduling FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba): perf score=2.188937
I20260812 06:18:46.374118 28092 maintenance_manager.cc:643] P 7a7ad99eae7d4cfe85fc871e66edf2b7: FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4070,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:46.374621 28208 maintenance_manager.cc:419] P 7a7ad99eae7d4cfe85fc871e66edf2b7: Scheduling MajorDeltaCompactionOp(86fc1a8e5ba14a46a1705b7cd5fd27ba): perf score=1.000000
I20260812 06:18:46.551445 28092 maintenance_manager.cc:643] P 7a7ad99eae7d4cfe85fc871e66edf2b7: MajorDeltaCompactionOp(86fc1a8e5ba14a46a1705b7cd5fd27ba) complete. Timing: real 0.177s	user 0.122s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815681,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":664,"lbm_read_time_us":12177,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28758,"lbm_writes_lt_1ms":543,"mutex_wait_us":188,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6528,"update_count":2500}
I20260812 06:18:46.552279 28208 maintenance_manager.cc:419] P 7a7ad99eae7d4cfe85fc871e66edf2b7: Scheduling FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba): perf score=11.118625
I20260812 06:18:46.587529 28092 maintenance_manager.cc:643] P 7a7ad99eae7d4cfe85fc871e66edf2b7: FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba) complete. Timing: real 0.035s	user 0.019s	sys 0.013s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15130,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:46.588091 28208 maintenance_manager.cc:419] P 7a7ad99eae7d4cfe85fc871e66edf2b7: Scheduling FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba): perf score=2.188937
I20260812 06:18:46.606586 28092 maintenance_manager.cc:643] P 7a7ad99eae7d4cfe85fc871e66edf2b7: FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba) complete. Timing: real 0.018s	user 0.002s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5294,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:46.607021 28208 maintenance_manager.cc:419] P 7a7ad99eae7d4cfe85fc871e66edf2b7: Scheduling FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba): perf score=2.188937
I20260812 06:18:46.617573 28092 maintenance_manager.cc:643] P 7a7ad99eae7d4cfe85fc871e66edf2b7: FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4135,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:46.617993 28208 maintenance_manager.cc:419] P 7a7ad99eae7d4cfe85fc871e66edf2b7: Scheduling MajorDeltaCompactionOp(86fc1a8e5ba14a46a1705b7cd5fd27ba): perf score=1.000000
I20260812 06:18:46.806752 28092 maintenance_manager.cc:643] P 7a7ad99eae7d4cfe85fc871e66edf2b7: MajorDeltaCompactionOp(86fc1a8e5ba14a46a1705b7cd5fd27ba) complete. Timing: real 0.189s	user 0.161s	sys 0.026s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815794,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":512,"lbm_read_time_us":9920,"lbm_reads_lt_1ms":573,"lbm_write_time_us":35517,"lbm_writes_lt_1ms":543,"mutex_wait_us":31,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":17408,"update_count":2500}
I20260812 06:18:46.807377 28208 maintenance_manager.cc:419] P 7a7ad99eae7d4cfe85fc871e66edf2b7: Scheduling FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba): perf score=14.095187
I20260812 06:18:46.881053 28092 maintenance_manager.cc:643] P 7a7ad99eae7d4cfe85fc871e66edf2b7: FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba) complete. Timing: real 0.073s	user 0.044s	sys 0.025s Metrics: {"bytes_written":16409938,"delete_count":0,"lbm_write_time_us":29909,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:46.881698 28208 maintenance_manager.cc:419] P 7a7ad99eae7d4cfe85fc871e66edf2b7: Scheduling FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba): perf score=3.181125
I20260812 06:18:46.902606 28092 maintenance_manager.cc:643] P 7a7ad99eae7d4cfe85fc871e66edf2b7: FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba) complete. Timing: real 0.021s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4529,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:46.903088 28208 maintenance_manager.cc:419] P 7a7ad99eae7d4cfe85fc871e66edf2b7: Scheduling FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba): perf score=2.188937
I20260812 06:18:46.916033 28092 maintenance_manager.cc:643] P 7a7ad99eae7d4cfe85fc871e66edf2b7: FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba) complete. Timing: real 0.013s	user 0.002s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5008,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:46.916505 28208 maintenance_manager.cc:419] P 7a7ad99eae7d4cfe85fc871e66edf2b7: Scheduling MajorDeltaCompactionOp(86fc1a8e5ba14a46a1705b7cd5fd27ba): perf score=1.000000
I20260812 06:18:47.113358 28092 maintenance_manager.cc:643] P 7a7ad99eae7d4cfe85fc871e66edf2b7: MajorDeltaCompactionOp(86fc1a8e5ba14a46a1705b7cd5fd27ba) complete. Timing: real 0.197s	user 0.151s	sys 0.043s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918241,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":669,"lbm_read_time_us":14674,"lbm_reads_lt_1ms":673,"lbm_write_time_us":41298,"lbm_writes_lt_1ms":643,"mutex_wait_us":294,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":11648,"update_count":3000}
I20260812 06:18:47.113903 28208 maintenance_manager.cc:419] P 7a7ad99eae7d4cfe85fc871e66edf2b7: Scheduling FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba): perf score=10.126437
I20260812 06:18:47.167173 28092 maintenance_manager.cc:643] P 7a7ad99eae7d4cfe85fc871e66edf2b7: FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba) complete. Timing: real 0.053s	user 0.024s	sys 0.023s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":23937,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:47.167769 28208 maintenance_manager.cc:419] P 7a7ad99eae7d4cfe85fc871e66edf2b7: Scheduling FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba): perf score=2.188937
I20260812 06:18:47.183549 28092 maintenance_manager.cc:643] P 7a7ad99eae7d4cfe85fc871e66edf2b7: FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba) complete. Timing: real 0.016s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6021,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:47.184304 28208 maintenance_manager.cc:419] P 7a7ad99eae7d4cfe85fc871e66edf2b7: Scheduling FlushMRSOp(86fc1a8e5ba14a46a1705b7cd5fd27ba): perf score=1.000000
I20260812 06:18:47.218215 28092 maintenance_manager.cc:643] P 7a7ad99eae7d4cfe85fc871e66edf2b7: FlushMRSOp(86fc1a8e5ba14a46a1705b7cd5fd27ba) complete. Timing: real 0.034s	user 0.028s	sys 0.004s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":56,"dirs.run_cpu_time_us":259,"dirs.run_wall_time_us":1577,"drs_written":1,"lbm_read_time_us":83,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2009,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:47.218799 28208 maintenance_manager.cc:419] P 7a7ad99eae7d4cfe85fc871e66edf2b7: Scheduling LogGCOp(86fc1a8e5ba14a46a1705b7cd5fd27ba): free 121006420 bytes of WAL
I20260812 06:18:47.219030 28092 log_reader.cc:385] T 86fc1a8e5ba14a46a1705b7cd5fd27ba: removed 12 log segments from log reader
I20260812 06:18:47.219074 28092 log.cc:1079] T 86fc1a8e5ba14a46a1705b7cd5fd27ba P 7a7ad99eae7d4cfe85fc871e66edf2b7: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/86fc1a8e5ba14a46a1705b7cd5fd27ba/wal-000000003 (ops 11-15)
I20260812 06:18:47.219102 28092 log.cc:1079] T 86fc1a8e5ba14a46a1705b7cd5fd27ba P 7a7ad99eae7d4cfe85fc871e66edf2b7: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/86fc1a8e5ba14a46a1705b7cd5fd27ba/wal-000000004 (ops 16-20)
I20260812 06:18:47.219164 28092 log.cc:1079] T 86fc1a8e5ba14a46a1705b7cd5fd27ba P 7a7ad99eae7d4cfe85fc871e66edf2b7: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/86fc1a8e5ba14a46a1705b7cd5fd27ba/wal-000000005 (ops 21-25)
I20260812 06:18:47.219197 28092 log.cc:1079] T 86fc1a8e5ba14a46a1705b7cd5fd27ba P 7a7ad99eae7d4cfe85fc871e66edf2b7: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/86fc1a8e5ba14a46a1705b7cd5fd27ba/wal-000000006 (ops 26-30)
I20260812 06:18:47.219233 28092 log.cc:1079] T 86fc1a8e5ba14a46a1705b7cd5fd27ba P 7a7ad99eae7d4cfe85fc871e66edf2b7: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/86fc1a8e5ba14a46a1705b7cd5fd27ba/wal-000000007 (ops 31-34)
I20260812 06:18:47.219281 28092 log.cc:1079] T 86fc1a8e5ba14a46a1705b7cd5fd27ba P 7a7ad99eae7d4cfe85fc871e66edf2b7: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/86fc1a8e5ba14a46a1705b7cd5fd27ba/wal-000000008 (ops 35-39)
I20260812 06:18:47.219331 28092 log.cc:1079] T 86fc1a8e5ba14a46a1705b7cd5fd27ba P 7a7ad99eae7d4cfe85fc871e66edf2b7: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/86fc1a8e5ba14a46a1705b7cd5fd27ba/wal-000000009 (ops 40-44)
I20260812 06:18:47.219368 28092 log.cc:1079] T 86fc1a8e5ba14a46a1705b7cd5fd27ba P 7a7ad99eae7d4cfe85fc871e66edf2b7: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/86fc1a8e5ba14a46a1705b7cd5fd27ba/wal-000000010 (ops 45-49)
I20260812 06:18:47.219408 28092 log.cc:1079] T 86fc1a8e5ba14a46a1705b7cd5fd27ba P 7a7ad99eae7d4cfe85fc871e66edf2b7: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/86fc1a8e5ba14a46a1705b7cd5fd27ba/wal-000000011 (ops 50-54)
I20260812 06:18:47.219446 28092 log.cc:1079] T 86fc1a8e5ba14a46a1705b7cd5fd27ba P 7a7ad99eae7d4cfe85fc871e66edf2b7: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/86fc1a8e5ba14a46a1705b7cd5fd27ba/wal-000000012 (ops 55-59)
I20260812 06:18:47.219485 28092 log.cc:1079] T 86fc1a8e5ba14a46a1705b7cd5fd27ba P 7a7ad99eae7d4cfe85fc871e66edf2b7: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/86fc1a8e5ba14a46a1705b7cd5fd27ba/wal-000000013 (ops 60-64)
I20260812 06:18:47.219523 28092 log.cc:1079] T 86fc1a8e5ba14a46a1705b7cd5fd27ba P 7a7ad99eae7d4cfe85fc871e66edf2b7: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/86fc1a8e5ba14a46a1705b7cd5fd27ba/wal-000000014 (ops 65-69)
I20260812 06:18:47.246263 28092 maintenance_manager.cc:643] P 7a7ad99eae7d4cfe85fc871e66edf2b7: LogGCOp(86fc1a8e5ba14a46a1705b7cd5fd27ba) complete. Timing: real 0.027s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:18:47.246665 28208 maintenance_manager.cc:419] P 7a7ad99eae7d4cfe85fc871e66edf2b7: Scheduling UndoDeltaBlockGCOp(86fc1a8e5ba14a46a1705b7cd5fd27ba): 448 bytes on disk
I20260812 06:18:47.247051 28092 maintenance_manager.cc:643] P 7a7ad99eae7d4cfe85fc871e66edf2b7: UndoDeltaBlockGCOp(86fc1a8e5ba14a46a1705b7cd5fd27ba) 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:47.247494 28208 maintenance_manager.cc:419] P 7a7ad99eae7d4cfe85fc871e66edf2b7: Scheduling FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba): perf score=3.181125
I20260812 06:18:47.269861 28092 maintenance_manager.cc:643] P 7a7ad99eae7d4cfe85fc871e66edf2b7: FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba) complete. Timing: real 0.022s	user 0.010s	sys 0.010s Metrics: {"bytes_written":4882125,"delete_count":0,"lbm_write_time_us":4764,"lbm_writes_lt_1ms":122,"reinsert_count":0,"update_count":595}
I20260812 06:18:47.270331 28208 maintenance_manager.cc:419] P 7a7ad99eae7d4cfe85fc871e66edf2b7: Scheduling FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba): perf score=2.188937
I20260812 06:18:47.279268 28092 maintenance_manager.cc:643] P 7a7ad99eae7d4cfe85fc871e66edf2b7: FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba) complete. Timing: real 0.009s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3323180,"delete_count":0,"lbm_write_time_us":3394,"lbm_writes_lt_1ms":84,"reinsert_count":0,"update_count":405}
I20260812 06:18:47.279683 28208 maintenance_manager.cc:419] P 7a7ad99eae7d4cfe85fc871e66edf2b7: Scheduling MajorDeltaCompactionOp(86fc1a8e5ba14a46a1705b7cd5fd27ba): perf score=1.000000
I20260812 06:18:47.476604 28092 maintenance_manager.cc:643] P 7a7ad99eae7d4cfe85fc871e66edf2b7: MajorDeltaCompactionOp(86fc1a8e5ba14a46a1705b7cd5fd27ba) complete. Timing: real 0.197s	user 0.133s	sys 0.063s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918323,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":2109,"lbm_read_time_us":14605,"lbm_reads_lt_1ms":674,"lbm_write_time_us":32135,"lbm_writes_lt_1ms":643,"mutex_wait_us":798,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":21760,"thread_start_us":77,"threads_started":1,"update_count":3000}
I20260812 06:18:47.477207 28208 maintenance_manager.cc:419] P 7a7ad99eae7d4cfe85fc871e66edf2b7: Scheduling FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba): perf score=14.095187
I20260812 06:18:47.541193 28092 maintenance_manager.cc:643] P 7a7ad99eae7d4cfe85fc871e66edf2b7: FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba) complete. Timing: real 0.064s	user 0.039s	sys 0.023s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":24027,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:47.541705 28208 maintenance_manager.cc:419] P 7a7ad99eae7d4cfe85fc871e66edf2b7: Scheduling FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba): perf score=2.188937
I20260812 06:18:47.553519 28092 maintenance_manager.cc:643] P 7a7ad99eae7d4cfe85fc871e66edf2b7: FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4126,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:47.553957 28208 maintenance_manager.cc:419] P 7a7ad99eae7d4cfe85fc871e66edf2b7: Scheduling MajorDeltaCompactionOp(86fc1a8e5ba14a46a1705b7cd5fd27ba): perf score=1.000000
I20260812 06:18:47.728751 28092 maintenance_manager.cc:643] P 7a7ad99eae7d4cfe85fc871e66edf2b7: MajorDeltaCompactionOp(86fc1a8e5ba14a46a1705b7cd5fd27ba) complete. Timing: real 0.175s	user 0.118s	sys 0.051s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":873,"lbm_read_time_us":11995,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27576,"lbm_writes_lt_1ms":543,"mutex_wait_us":280,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3584,"update_count":2500}
I20260812 06:18:47.729341 28208 maintenance_manager.cc:419] P 7a7ad99eae7d4cfe85fc871e66edf2b7: Scheduling FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba): perf score=14.095187
I20260812 06:18:47.784531 28092 maintenance_manager.cc:643] P 7a7ad99eae7d4cfe85fc871e66edf2b7: FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba) complete. Timing: real 0.055s	user 0.035s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24644,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:47.785033 28208 maintenance_manager.cc:419] P 7a7ad99eae7d4cfe85fc871e66edf2b7: Scheduling FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba): perf score=2.188937
I20260812 06:18:47.807531 28092 maintenance_manager.cc:643] P 7a7ad99eae7d4cfe85fc871e66edf2b7: FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba) complete. Timing: real 0.022s	user 0.003s	sys 0.014s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7228,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":102,"reinsert_count":0,"update_count":500}
I20260812 06:18:47.808084 28208 maintenance_manager.cc:419] P 7a7ad99eae7d4cfe85fc871e66edf2b7: Scheduling MajorDeltaCompactionOp(86fc1a8e5ba14a46a1705b7cd5fd27ba): perf score=1.000000
I20260812 06:18:47.990288 28092 maintenance_manager.cc:643] P 7a7ad99eae7d4cfe85fc871e66edf2b7: MajorDeltaCompactionOp(86fc1a8e5ba14a46a1705b7cd5fd27ba) complete. Timing: real 0.182s	user 0.127s	sys 0.053s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":295,"lbm_read_time_us":12497,"lbm_reads_lt_1ms":564,"lbm_write_time_us":29257,"lbm_writes_lt_1ms":543,"mutex_wait_us":43,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8064,"update_count":2500}
I20260812 06:18:47.990959 28208 maintenance_manager.cc:419] P 7a7ad99eae7d4cfe85fc871e66edf2b7: Scheduling FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba): perf score=14.095187
I20260812 06:18:48.045781 28092 maintenance_manager.cc:643] P 7a7ad99eae7d4cfe85fc871e66edf2b7: FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba) complete. Timing: real 0.055s	user 0.026s	sys 0.027s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24039,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:48.046355 28208 maintenance_manager.cc:419] P 7a7ad99eae7d4cfe85fc871e66edf2b7: Scheduling FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba): perf score=2.188937
I20260812 06:18:48.058698 28092 maintenance_manager.cc:643] P 7a7ad99eae7d4cfe85fc871e66edf2b7: FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba) complete. Timing: real 0.012s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4047,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:48.059276 28208 maintenance_manager.cc:419] P 7a7ad99eae7d4cfe85fc871e66edf2b7: Scheduling MajorDeltaCompactionOp(86fc1a8e5ba14a46a1705b7cd5fd27ba): perf score=1.000000
I20260812 06:18:48.233631 28092 maintenance_manager.cc:643] P 7a7ad99eae7d4cfe85fc871e66edf2b7: MajorDeltaCompactionOp(86fc1a8e5ba14a46a1705b7cd5fd27ba) complete. Timing: real 0.174s	user 0.124s	sys 0.043s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":174,"lbm_read_time_us":10145,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27744,"lbm_writes_lt_1ms":543,"mutex_wait_us":21,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8192,"update_count":2500}
I20260812 06:18:48.234321 28208 maintenance_manager.cc:419] P 7a7ad99eae7d4cfe85fc871e66edf2b7: Scheduling FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba): perf score=14.095187
I20260812 06:18:48.285718 28092 maintenance_manager.cc:643] P 7a7ad99eae7d4cfe85fc871e66edf2b7: FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba) complete. Timing: real 0.051s	user 0.023s	sys 0.024s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21502,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:48.286262 28208 maintenance_manager.cc:419] P 7a7ad99eae7d4cfe85fc871e66edf2b7: Scheduling FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba): perf score=2.188937
I20260812 06:18:48.297541 28092 maintenance_manager.cc:643] P 7a7ad99eae7d4cfe85fc871e66edf2b7: FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba) complete. Timing: real 0.011s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4220,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:48.298026 28208 maintenance_manager.cc:419] P 7a7ad99eae7d4cfe85fc871e66edf2b7: Scheduling MajorDeltaCompactionOp(86fc1a8e5ba14a46a1705b7cd5fd27ba): perf score=1.000000
I20260812 06:18:48.439455 28092 maintenance_manager.cc:643] P 7a7ad99eae7d4cfe85fc871e66edf2b7: MajorDeltaCompactionOp(86fc1a8e5ba14a46a1705b7cd5fd27ba) complete. Timing: real 0.141s	user 0.119s	sys 0.020s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":633,"lbm_read_time_us":9855,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28941,"lbm_writes_lt_1ms":543,"mutex_wait_us":26,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11776,"update_count":2500}
I20260812 06:18:48.440341 28208 maintenance_manager.cc:419] P 7a7ad99eae7d4cfe85fc871e66edf2b7: Scheduling FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba): perf score=10.126437
I20260812 06:18:48.468886 28092 maintenance_manager.cc:643] P 7a7ad99eae7d4cfe85fc871e66edf2b7: FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba) complete. Timing: real 0.028s	user 0.027s	sys 0.000s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":12372,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:48.469453 28208 maintenance_manager.cc:419] P 7a7ad99eae7d4cfe85fc871e66edf2b7: Scheduling FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba): perf score=2.188937
I20260812 06:18:48.489283 28092 maintenance_manager.cc:643] P 7a7ad99eae7d4cfe85fc871e66edf2b7: FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba) complete. Timing: real 0.020s	user 0.009s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5606,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:48.489864 28208 maintenance_manager.cc:419] P 7a7ad99eae7d4cfe85fc871e66edf2b7: Scheduling MajorDeltaCompactionOp(86fc1a8e5ba14a46a1705b7cd5fd27ba): perf score=1.000000
I20260812 06:18:48.606398 28092 maintenance_manager.cc:643] P 7a7ad99eae7d4cfe85fc871e66edf2b7: MajorDeltaCompactionOp(86fc1a8e5ba14a46a1705b7cd5fd27ba) complete. Timing: real 0.116s	user 0.086s	sys 0.029s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713270,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1033,"lbm_read_time_us":7027,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23365,"lbm_writes_lt_1ms":443,"mutex_wait_us":343,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":30464,"update_count":2000}
I20260812 06:18:48.607012 28208 maintenance_manager.cc:419] P 7a7ad99eae7d4cfe85fc871e66edf2b7: Scheduling FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba): perf score=10.126437
I20260812 06:18:48.649350 28092 maintenance_manager.cc:643] P 7a7ad99eae7d4cfe85fc871e66edf2b7: FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba) complete. Timing: real 0.042s	user 0.020s	sys 0.015s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16043,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:48.649857 28208 maintenance_manager.cc:419] P 7a7ad99eae7d4cfe85fc871e66edf2b7: Scheduling FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba): perf score=2.188937
I20260812 06:18:48.659648 28092 maintenance_manager.cc:643] P 7a7ad99eae7d4cfe85fc871e66edf2b7: FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3811,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:48.660189 28208 maintenance_manager.cc:419] P 7a7ad99eae7d4cfe85fc871e66edf2b7: Scheduling FlushMRSOp(86fc1a8e5ba14a46a1705b7cd5fd27ba): perf score=1.000000
I20260812 06:18:48.693787 28092 maintenance_manager.cc:643] P 7a7ad99eae7d4cfe85fc871e66edf2b7: FlushMRSOp(86fc1a8e5ba14a46a1705b7cd5fd27ba) complete. Timing: real 0.033s	user 0.031s	sys 0.001s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":57,"dirs.run_cpu_time_us":135,"dirs.run_wall_time_us":1084,"drs_written":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1869,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:48.694430 28208 maintenance_manager.cc:419] P 7a7ad99eae7d4cfe85fc871e66edf2b7: Scheduling LogGCOp(86fc1a8e5ba14a46a1705b7cd5fd27ba): free 120553388 bytes of WAL
I20260812 06:18:48.694712 28092 log_reader.cc:385] T 86fc1a8e5ba14a46a1705b7cd5fd27ba: removed 12 log segments from log reader
I20260812 06:18:48.694777 28092 log.cc:1079] T 86fc1a8e5ba14a46a1705b7cd5fd27ba P 7a7ad99eae7d4cfe85fc871e66edf2b7: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/86fc1a8e5ba14a46a1705b7cd5fd27ba/wal-000000015 (ops 70-74)
I20260812 06:18:48.694818 28092 log.cc:1079] T 86fc1a8e5ba14a46a1705b7cd5fd27ba P 7a7ad99eae7d4cfe85fc871e66edf2b7: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/86fc1a8e5ba14a46a1705b7cd5fd27ba/wal-000000016 (ops 75-78)
I20260812 06:18:48.694849 28092 log.cc:1079] T 86fc1a8e5ba14a46a1705b7cd5fd27ba P 7a7ad99eae7d4cfe85fc871e66edf2b7: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/86fc1a8e5ba14a46a1705b7cd5fd27ba/wal-000000017 (ops 79-83)
I20260812 06:18:48.694880 28092 log.cc:1079] T 86fc1a8e5ba14a46a1705b7cd5fd27ba P 7a7ad99eae7d4cfe85fc871e66edf2b7: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/86fc1a8e5ba14a46a1705b7cd5fd27ba/wal-000000018 (ops 84-88)
I20260812 06:18:48.694909 28092 log.cc:1079] T 86fc1a8e5ba14a46a1705b7cd5fd27ba P 7a7ad99eae7d4cfe85fc871e66edf2b7: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/86fc1a8e5ba14a46a1705b7cd5fd27ba/wal-000000019 (ops 89-93)
I20260812 06:18:48.694945 28092 log.cc:1079] T 86fc1a8e5ba14a46a1705b7cd5fd27ba P 7a7ad99eae7d4cfe85fc871e66edf2b7: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/86fc1a8e5ba14a46a1705b7cd5fd27ba/wal-000000020 (ops 94-98)
I20260812 06:18:48.694975 28092 log.cc:1079] T 86fc1a8e5ba14a46a1705b7cd5fd27ba P 7a7ad99eae7d4cfe85fc871e66edf2b7: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/86fc1a8e5ba14a46a1705b7cd5fd27ba/wal-000000021 (ops 99-103)
I20260812 06:18:48.695005 28092 log.cc:1079] T 86fc1a8e5ba14a46a1705b7cd5fd27ba P 7a7ad99eae7d4cfe85fc871e66edf2b7: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/86fc1a8e5ba14a46a1705b7cd5fd27ba/wal-000000022 (ops 104-108)
I20260812 06:18:48.695035 28092 log.cc:1079] T 86fc1a8e5ba14a46a1705b7cd5fd27ba P 7a7ad99eae7d4cfe85fc871e66edf2b7: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/86fc1a8e5ba14a46a1705b7cd5fd27ba/wal-000000023 (ops 109-113)
I20260812 06:18:48.695065 28092 log.cc:1079] T 86fc1a8e5ba14a46a1705b7cd5fd27ba P 7a7ad99eae7d4cfe85fc871e66edf2b7: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/86fc1a8e5ba14a46a1705b7cd5fd27ba/wal-000000024 (ops 114-118)
I20260812 06:18:48.695093 28092 log.cc:1079] T 86fc1a8e5ba14a46a1705b7cd5fd27ba P 7a7ad99eae7d4cfe85fc871e66edf2b7: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/86fc1a8e5ba14a46a1705b7cd5fd27ba/wal-000000025 (ops 119-122)
I20260812 06:18:48.695127 28092 log.cc:1079] T 86fc1a8e5ba14a46a1705b7cd5fd27ba P 7a7ad99eae7d4cfe85fc871e66edf2b7: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/86fc1a8e5ba14a46a1705b7cd5fd27ba/wal-000000026 (ops 123-127)
I20260812 06:18:48.725907 28092 maintenance_manager.cc:643] P 7a7ad99eae7d4cfe85fc871e66edf2b7: LogGCOp(86fc1a8e5ba14a46a1705b7cd5fd27ba) complete. Timing: real 0.031s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:18:48.726459 28208 maintenance_manager.cc:419] P 7a7ad99eae7d4cfe85fc871e66edf2b7: Scheduling FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba): perf score=2.188937
I20260812 06:18:48.744680 28092 maintenance_manager.cc:643] P 7a7ad99eae7d4cfe85fc871e66edf2b7: FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba) complete. Timing: real 0.018s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4323,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:48.745100 28208 maintenance_manager.cc:419] P 7a7ad99eae7d4cfe85fc871e66edf2b7: Scheduling FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba): perf score=2.188937
I20260812 06:18:48.755272 28092 maintenance_manager.cc:643] P 7a7ad99eae7d4cfe85fc871e66edf2b7: FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4079,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:48.755673 28208 maintenance_manager.cc:419] P 7a7ad99eae7d4cfe85fc871e66edf2b7: Scheduling UndoDeltaBlockGCOp(86fc1a8e5ba14a46a1705b7cd5fd27ba): 472 bytes on disk
I20260812 06:18:48.756112 28092 maintenance_manager.cc:643] P 7a7ad99eae7d4cfe85fc871e66edf2b7: UndoDeltaBlockGCOp(86fc1a8e5ba14a46a1705b7cd5fd27ba) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4}
I20260812 06:18:48.757031 28208 maintenance_manager.cc:419] P 7a7ad99eae7d4cfe85fc871e66edf2b7: Scheduling MajorDeltaCompactionOp(86fc1a8e5ba14a46a1705b7cd5fd27ba): perf score=1.000000
I20260812 06:18:48.936414 28092 maintenance_manager.cc:643] P 7a7ad99eae7d4cfe85fc871e66edf2b7: MajorDeltaCompactionOp(86fc1a8e5ba14a46a1705b7cd5fd27ba) complete. Timing: real 0.179s	user 0.141s	sys 0.036s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918332,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":4924,"lbm_read_time_us":11788,"lbm_reads_lt_1ms":674,"lbm_write_time_us":35901,"lbm_writes_lt_1ms":643,"mutex_wait_us":2340,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":75,"threads_started":1,"update_count":3000}
I20260812 06:18:48.936982 28208 maintenance_manager.cc:419] P 7a7ad99eae7d4cfe85fc871e66edf2b7: Scheduling FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba): perf score=14.095187
I20260812 06:18:48.985396 28092 maintenance_manager.cc:643] P 7a7ad99eae7d4cfe85fc871e66edf2b7: FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba) complete. Timing: real 0.048s	user 0.031s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21791,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:48.985865 28208 maintenance_manager.cc:419] P 7a7ad99eae7d4cfe85fc871e66edf2b7: Scheduling FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba): perf score=2.188937
I20260812 06:18:48.997485 28092 maintenance_manager.cc:643] P 7a7ad99eae7d4cfe85fc871e66edf2b7: FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba) complete. Timing: real 0.011s	user 0.004s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4000,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:48.997990 28208 maintenance_manager.cc:419] P 7a7ad99eae7d4cfe85fc871e66edf2b7: Scheduling MajorDeltaCompactionOp(86fc1a8e5ba14a46a1705b7cd5fd27ba): perf score=1.000000
I20260812 06:18:49.164033 28092 maintenance_manager.cc:643] P 7a7ad99eae7d4cfe85fc871e66edf2b7: MajorDeltaCompactionOp(86fc1a8e5ba14a46a1705b7cd5fd27ba) complete. Timing: real 0.166s	user 0.127s	sys 0.029s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1104,"lbm_read_time_us":10406,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31059,"lbm_writes_lt_1ms":543,"mutex_wait_us":59,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6912,"update_count":2500}
I20260812 06:18:49.164630 28208 maintenance_manager.cc:419] P 7a7ad99eae7d4cfe85fc871e66edf2b7: Scheduling FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba): perf score=14.095187
I20260812 06:18:49.209744 28092 maintenance_manager.cc:643] P 7a7ad99eae7d4cfe85fc871e66edf2b7: FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba) complete. Timing: real 0.045s	user 0.020s	sys 0.023s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":19795,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:49.210201 28208 maintenance_manager.cc:419] P 7a7ad99eae7d4cfe85fc871e66edf2b7: Scheduling MajorDeltaCompactionOp(86fc1a8e5ba14a46a1705b7cd5fd27ba): perf score=1.000000
I20260812 06:18:49.377313 28092 maintenance_manager.cc:643] P 7a7ad99eae7d4cfe85fc871e66edf2b7: MajorDeltaCompactionOp(86fc1a8e5ba14a46a1705b7cd5fd27ba) complete. Timing: real 0.167s	user 0.097s	sys 0.057s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713154,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":2685,"lbm_read_time_us":9345,"lbm_reads_lt_1ms":467,"lbm_write_time_us":25754,"lbm_writes_lt_1ms":443,"mutex_wait_us":1808,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4608,"update_count":2000}
I20260812 06:18:49.378340 28208 maintenance_manager.cc:419] P 7a7ad99eae7d4cfe85fc871e66edf2b7: Scheduling FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba): perf score=11.118625
I20260812 06:18:49.425838 28092 maintenance_manager.cc:643] P 7a7ad99eae7d4cfe85fc871e66edf2b7: FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba) complete. Timing: real 0.047s	user 0.024s	sys 0.017s Metrics: {"bytes_written":13538208,"delete_count":0,"lbm_write_time_us":19298,"lbm_writes_lt_1ms":333,"reinsert_count":0,"update_count":1650}
I20260812 06:18:49.426338 28208 maintenance_manager.cc:419] P 7a7ad99eae7d4cfe85fc871e66edf2b7: Scheduling FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba): perf score=2.188937
I20260812 06:18:49.442613 28092 maintenance_manager.cc:643] P 7a7ad99eae7d4cfe85fc871e66edf2b7: FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba) complete. Timing: real 0.016s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3282159,"delete_count":0,"lbm_write_time_us":5207,"lbm_writes_lt_1ms":83,"reinsert_count":0,"update_count":400}
I20260812 06:18:49.443049 28208 maintenance_manager.cc:419] P 7a7ad99eae7d4cfe85fc871e66edf2b7: Scheduling FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba): perf score=2.188937
I20260812 06:18:49.452241 28092 maintenance_manager.cc:643] P 7a7ad99eae7d4cfe85fc871e66edf2b7: FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba) complete. Timing: real 0.009s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3603,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:49.452670 28208 maintenance_manager.cc:419] P 7a7ad99eae7d4cfe85fc871e66edf2b7: Scheduling MajorDeltaCompactionOp(86fc1a8e5ba14a46a1705b7cd5fd27ba): perf score=1.000000
I20260812 06:18:49.641366 28092 maintenance_manager.cc:643] P 7a7ad99eae7d4cfe85fc871e66edf2b7: MajorDeltaCompactionOp(86fc1a8e5ba14a46a1705b7cd5fd27ba) complete. Timing: real 0.189s	user 0.107s	sys 0.068s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815767,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":162,"lbm_read_time_us":11688,"lbm_reads_lt_1ms":573,"lbm_write_time_us":31197,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14208,"update_count":2500}
I20260812 06:18:49.641928 28208 maintenance_manager.cc:419] P 7a7ad99eae7d4cfe85fc871e66edf2b7: Scheduling FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba): perf score=14.095187
I20260812 06:18:49.695667 28092 maintenance_manager.cc:643] P 7a7ad99eae7d4cfe85fc871e66edf2b7: FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba) complete. Timing: real 0.054s	user 0.024s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21355,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:49.696218 28208 maintenance_manager.cc:419] P 7a7ad99eae7d4cfe85fc871e66edf2b7: Scheduling FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba): perf score=2.188937
I20260812 06:18:49.707646 28092 maintenance_manager.cc:643] P 7a7ad99eae7d4cfe85fc871e66edf2b7: FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba) complete. Timing: real 0.011s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4217,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:49.708405 28208 maintenance_manager.cc:419] P 7a7ad99eae7d4cfe85fc871e66edf2b7: Scheduling MajorDeltaCompactionOp(86fc1a8e5ba14a46a1705b7cd5fd27ba): perf score=1.000000
I20260812 06:18:49.872838 28092 maintenance_manager.cc:643] P 7a7ad99eae7d4cfe85fc871e66edf2b7: MajorDeltaCompactionOp(86fc1a8e5ba14a46a1705b7cd5fd27ba) complete. Timing: real 0.164s	user 0.126s	sys 0.028s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":224,"lbm_read_time_us":10911,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31616,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8960,"update_count":2500}
I20260812 06:18:49.873381 28208 maintenance_manager.cc:419] P 7a7ad99eae7d4cfe85fc871e66edf2b7: Scheduling FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba): perf score=14.095187
I20260812 06:18:49.929764 28092 maintenance_manager.cc:643] P 7a7ad99eae7d4cfe85fc871e66edf2b7: FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba) complete. Timing: real 0.056s	user 0.023s	sys 0.028s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23509,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:49.930306 28208 maintenance_manager.cc:419] P 7a7ad99eae7d4cfe85fc871e66edf2b7: Scheduling FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba): perf score=2.188937
I20260812 06:18:49.941608 28092 maintenance_manager.cc:643] P 7a7ad99eae7d4cfe85fc871e66edf2b7: FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4087,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:49.942099 28208 maintenance_manager.cc:419] P 7a7ad99eae7d4cfe85fc871e66edf2b7: Scheduling MajorDeltaCompactionOp(86fc1a8e5ba14a46a1705b7cd5fd27ba): perf score=1.000000
I20260812 06:18:50.094749 28092 maintenance_manager.cc:643] P 7a7ad99eae7d4cfe85fc871e66edf2b7: MajorDeltaCompactionOp(86fc1a8e5ba14a46a1705b7cd5fd27ba) complete. Timing: real 0.152s	user 0.108s	sys 0.031s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":205,"lbm_read_time_us":9017,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28575,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":20096,"update_count":2500}
I20260812 06:18:50.095476 28208 maintenance_manager.cc:419] P 7a7ad99eae7d4cfe85fc871e66edf2b7: Scheduling FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba): perf score=14.095187
I20260812 06:18:50.149740 28092 maintenance_manager.cc:643] P 7a7ad99eae7d4cfe85fc871e66edf2b7: FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba) complete. Timing: real 0.054s	user 0.038s	sys 0.008s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":21216,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:50.150352 28208 maintenance_manager.cc:419] P 7a7ad99eae7d4cfe85fc871e66edf2b7: Scheduling FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba): perf score=2.188937
I20260812 06:18:50.162072 28092 maintenance_manager.cc:643] P 7a7ad99eae7d4cfe85fc871e66edf2b7: FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba) complete. Timing: real 0.012s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4419,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:50.162564 28208 maintenance_manager.cc:419] P 7a7ad99eae7d4cfe85fc871e66edf2b7: Scheduling FlushMRSOp(86fc1a8e5ba14a46a1705b7cd5fd27ba): perf score=1.000000
I20260812 06:18:50.194119 28092 maintenance_manager.cc:643] P 7a7ad99eae7d4cfe85fc871e66edf2b7: FlushMRSOp(86fc1a8e5ba14a46a1705b7cd5fd27ba) complete. Timing: real 0.031s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":65,"dirs.run_cpu_time_us":265,"dirs.run_wall_time_us":1187,"drs_written":1,"lbm_read_time_us":44,"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:50.194902 28208 maintenance_manager.cc:419] P 7a7ad99eae7d4cfe85fc871e66edf2b7: Scheduling LogGCOp(86fc1a8e5ba14a46a1705b7cd5fd27ba): free 124710567 bytes of WAL
I20260812 06:18:50.195164 28092 log_reader.cc:385] T 86fc1a8e5ba14a46a1705b7cd5fd27ba: removed 12 log segments from log reader
I20260812 06:18:50.195233 28092 log.cc:1079] T 86fc1a8e5ba14a46a1705b7cd5fd27ba P 7a7ad99eae7d4cfe85fc871e66edf2b7: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/86fc1a8e5ba14a46a1705b7cd5fd27ba/wal-000000027 (ops 128-132)
I20260812 06:18:50.195290 28092 log.cc:1079] T 86fc1a8e5ba14a46a1705b7cd5fd27ba P 7a7ad99eae7d4cfe85fc871e66edf2b7: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/86fc1a8e5ba14a46a1705b7cd5fd27ba/wal-000000028 (ops 133-137)
I20260812 06:18:50.195348 28092 log.cc:1079] T 86fc1a8e5ba14a46a1705b7cd5fd27ba P 7a7ad99eae7d4cfe85fc871e66edf2b7: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/86fc1a8e5ba14a46a1705b7cd5fd27ba/wal-000000029 (ops 138-142)
I20260812 06:18:50.195390 28092 log.cc:1079] T 86fc1a8e5ba14a46a1705b7cd5fd27ba P 7a7ad99eae7d4cfe85fc871e66edf2b7: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/86fc1a8e5ba14a46a1705b7cd5fd27ba/wal-000000030 (ops 143-147)
I20260812 06:18:50.195428 28092 log.cc:1079] T 86fc1a8e5ba14a46a1705b7cd5fd27ba P 7a7ad99eae7d4cfe85fc871e66edf2b7: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/86fc1a8e5ba14a46a1705b7cd5fd27ba/wal-000000031 (ops 148-152)
I20260812 06:18:50.195477 28092 log.cc:1079] T 86fc1a8e5ba14a46a1705b7cd5fd27ba P 7a7ad99eae7d4cfe85fc871e66edf2b7: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/86fc1a8e5ba14a46a1705b7cd5fd27ba/wal-000000032 (ops 153-157)
I20260812 06:18:50.195518 28092 log.cc:1079] T 86fc1a8e5ba14a46a1705b7cd5fd27ba P 7a7ad99eae7d4cfe85fc871e66edf2b7: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/86fc1a8e5ba14a46a1705b7cd5fd27ba/wal-000000033 (ops 158-162)
I20260812 06:18:50.195559 28092 log.cc:1079] T 86fc1a8e5ba14a46a1705b7cd5fd27ba P 7a7ad99eae7d4cfe85fc871e66edf2b7: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/86fc1a8e5ba14a46a1705b7cd5fd27ba/wal-000000034 (ops 163-167)
I20260812 06:18:50.195600 28092 log.cc:1079] T 86fc1a8e5ba14a46a1705b7cd5fd27ba P 7a7ad99eae7d4cfe85fc871e66edf2b7: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/86fc1a8e5ba14a46a1705b7cd5fd27ba/wal-000000035 (ops 168-172)
I20260812 06:18:50.195638 28092 log.cc:1079] T 86fc1a8e5ba14a46a1705b7cd5fd27ba P 7a7ad99eae7d4cfe85fc871e66edf2b7: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/86fc1a8e5ba14a46a1705b7cd5fd27ba/wal-000000036 (ops 173-177)
I20260812 06:18:50.195678 28092 log.cc:1079] T 86fc1a8e5ba14a46a1705b7cd5fd27ba P 7a7ad99eae7d4cfe85fc871e66edf2b7: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/86fc1a8e5ba14a46a1705b7cd5fd27ba/wal-000000037 (ops 178-182)
I20260812 06:18:50.195719 28092 log.cc:1079] T 86fc1a8e5ba14a46a1705b7cd5fd27ba P 7a7ad99eae7d4cfe85fc871e66edf2b7: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/86fc1a8e5ba14a46a1705b7cd5fd27ba/wal-000000038 (ops 183-187)
I20260812 06:18:50.227476 28092 maintenance_manager.cc:643] P 7a7ad99eae7d4cfe85fc871e66edf2b7: LogGCOp(86fc1a8e5ba14a46a1705b7cd5fd27ba) complete. Timing: real 0.032s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:18:50.228020 28208 maintenance_manager.cc:419] P 7a7ad99eae7d4cfe85fc871e66edf2b7: Scheduling FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba): perf score=4.173312
I20260812 06:18:50.247627 28092 maintenance_manager.cc:643] P 7a7ad99eae7d4cfe85fc871e66edf2b7: FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba) complete. Timing: real 0.019s	user 0.008s	sys 0.008s Metrics: {"bytes_written":5743635,"delete_count":0,"lbm_write_time_us":7552,"lbm_writes_lt_1ms":143,"reinsert_count":0,"update_count":700}
I20260812 06:18:50.248328 28208 maintenance_manager.cc:419] P 7a7ad99eae7d4cfe85fc871e66edf2b7: Scheduling LogGCOp(86fc1a8e5ba14a46a1705b7cd5fd27ba): free 12017952 bytes of WAL
I20260812 06:18:50.248643 28092 log_reader.cc:385] T 86fc1a8e5ba14a46a1705b7cd5fd27ba: removed 1 log segments from log reader
I20260812 06:18:50.248751 28092 log.cc:1079] T 86fc1a8e5ba14a46a1705b7cd5fd27ba P 7a7ad99eae7d4cfe85fc871e66edf2b7: Deleting log segment in path: /tmp/dist-test-task4AvDiX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519867826-27570-0/minicluster-data/ts-0-root/wals/86fc1a8e5ba14a46a1705b7cd5fd27ba/wal-000000039 (ops 188-192)
I20260812 06:18:50.252065 28092 maintenance_manager.cc:643] P 7a7ad99eae7d4cfe85fc871e66edf2b7: LogGCOp(86fc1a8e5ba14a46a1705b7cd5fd27ba) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:18:50.252570 28208 maintenance_manager.cc:419] P 7a7ad99eae7d4cfe85fc871e66edf2b7: Scheduling FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba): perf score=1.196750
I20260812 06:18:50.281236 28092 maintenance_manager.cc:643] P 7a7ad99eae7d4cfe85fc871e66edf2b7: FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba) complete. Timing: real 0.028s	user 0.008s	sys 0.012s Metrics: {"bytes_written":2461654,"delete_count":0,"lbm_write_time_us":4114,"lbm_writes_lt_1ms":63,"reinsert_count":0,"update_count":300}
I20260812 06:18:50.281767 28208 maintenance_manager.cc:419] P 7a7ad99eae7d4cfe85fc871e66edf2b7: Scheduling MajorDeltaCompactionOp(86fc1a8e5ba14a46a1705b7cd5fd27ba): perf score=1.000000
I20260812 06:18:50.437718 27570 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.835s	user 1.862s	sys 0.112s
I20260812 06:18:50.485819 28092 maintenance_manager.cc:643] P 7a7ad99eae7d4cfe85fc871e66edf2b7: MajorDeltaCompactionOp(86fc1a8e5ba14a46a1705b7cd5fd27ba) complete. Timing: real 0.204s	user 0.130s	sys 0.073s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020709,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":14416,"lbm_reads_lt_1ms":762,"lbm_write_time_us":37249,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":3500}
I20260812 06:18:50.486423 28208 maintenance_manager.cc:419] P 7a7ad99eae7d4cfe85fc871e66edf2b7: Scheduling UndoDeltaBlockGCOp(86fc1a8e5ba14a46a1705b7cd5fd27ba): 482 bytes on disk
I20260812 06:18:50.487003 28092 maintenance_manager.cc:643] P 7a7ad99eae7d4cfe85fc871e66edf2b7: UndoDeltaBlockGCOp(86fc1a8e5ba14a46a1705b7cd5fd27ba) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4}
I20260812 06:18:50.487617 28208 maintenance_manager.cc:419] P 7a7ad99eae7d4cfe85fc871e66edf2b7: Scheduling FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba): perf score=14.095187
I20260812 06:18:50.514066 27570 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.076s	user 0.002s	sys 0.000s
I20260812 06:18:50.514551 27570 tablet_server.cc:179] TabletServer@127.26.236.129:0 shutting down...
I20260812 06:18:50.544023 28092 maintenance_manager.cc:643] P 7a7ad99eae7d4cfe85fc871e66edf2b7: FlushDeltaMemStoresOp(86fc1a8e5ba14a46a1705b7cd5fd27ba) complete. Timing: real 0.056s	user 0.038s	sys 0.014s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21278,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:50.545183 27570 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:50.545475 27570 tablet_replica.cc:333] T 86fc1a8e5ba14a46a1705b7cd5fd27ba P 7a7ad99eae7d4cfe85fc871e66edf2b7: stopping tablet replica
I20260812 06:18:50.545607 27570 raft_consensus.cc:2243] T 86fc1a8e5ba14a46a1705b7cd5fd27ba P 7a7ad99eae7d4cfe85fc871e66edf2b7 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:50.545790 27570 raft_consensus.cc:2272] T 86fc1a8e5ba14a46a1705b7cd5fd27ba P 7a7ad99eae7d4cfe85fc871e66edf2b7 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:50.549268 27570 tablet_server.cc:196] TabletServer@127.26.236.129:0 shutdown complete.
I20260812 06:18:50.557601 27570 master.cc:562] Master@127.26.236.190:42971 shutting down...
I20260812 06:18:50.560745 27570 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 051eeab9a01d499599578ce4656e568b [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:50.560915 27570 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 051eeab9a01d499599578ce4656e568b [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:50.560999 27570 tablet_replica.cc:333] T 00000000000000000000000000000000 P 051eeab9a01d499599578ce4656e568b: stopping tablet replica
I20260812 06:18:50.574035 27570 master.cc:584] Master@127.26.236.190:42971 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5301 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10783 ms total)

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