[==========] 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:38.934069 31566 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.30.211.190:43023
I20260812 06:18:38.935077 31566 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:38.935678 31566 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:18:38.942345 31566 server_base.cc:1061] running on GCE node
W20260812 06:18:38.942288 31574 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:38.942337 31575 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:38.942569 31578 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:38.943123 31566 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:38.943238 31566 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:38.943284 31566 hybrid_clock.cc:648] HybridClock initialized: now 1786515518943282 us; error 0 us; skew 500 ppm
I20260812 06:18:38.945192 31566 webserver.cc:533] Webserver started at http://127.30.211.190:37783/ using document root <none> and password file <none>
I20260812 06:18:38.945739 31566 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:38.945822 31566 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:38.946084 31566 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:38.947777 31566 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518923217-31566-0/minicluster-data/master-0-root/instance:
uuid: "41668550618646a5800211fb2c076244"
format_stamp: "Formatted at 2026-08-12 06:18:38 on dist-test-slave-t3q3"
I20260812 06:18:38.951215 31566 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.001s	sys 0.002s
I20260812 06:18:38.953300 31586 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:38.954275 31566 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:18:38.954402 31566 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518923217-31566-0/minicluster-data/master-0-root
uuid: "41668550618646a5800211fb2c076244"
format_stamp: "Formatted at 2026-08-12 06:18:38 on dist-test-slave-t3q3"
I20260812 06:18:38.954501 31566 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518923217-31566-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518923217-31566-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518923217-31566-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:38.985749 31566 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:38.986478 31566 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:38.986673 31566 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:38.994885 31566 rpc_server.cc:307] RPC server started. Bound to: 127.30.211.190:43023
I20260812 06:18:38.994900 31665 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.30.211.190:43023 every 8 connection(s)
I20260812 06:18:38.997308 31668 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.002907 31668 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 41668550618646a5800211fb2c076244: Bootstrap starting.
I20260812 06:18:39.005412 31668 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 41668550618646a5800211fb2c076244: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:39.006350 31668 log.cc:826] T 00000000000000000000000000000000 P 41668550618646a5800211fb2c076244: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:39.008186 31668 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 41668550618646a5800211fb2c076244: No bootstrap required, opened a new log
I20260812 06:18:39.011016 31668 raft_consensus.cc:359] T 00000000000000000000000000000000 P 41668550618646a5800211fb2c076244 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "41668550618646a5800211fb2c076244" member_type: VOTER }
I20260812 06:18:39.011193 31668 raft_consensus.cc:385] T 00000000000000000000000000000000 P 41668550618646a5800211fb2c076244 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:39.011262 31668 raft_consensus.cc:740] T 00000000000000000000000000000000 P 41668550618646a5800211fb2c076244 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 41668550618646a5800211fb2c076244, State: Initialized, Role: FOLLOWER
I20260812 06:18:39.011879 31668 consensus_queue.cc:260] T 00000000000000000000000000000000 P 41668550618646a5800211fb2c076244 [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: "41668550618646a5800211fb2c076244" member_type: VOTER }
I20260812 06:18:39.012048 31668 raft_consensus.cc:399] T 00000000000000000000000000000000 P 41668550618646a5800211fb2c076244 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:39.012147 31668 raft_consensus.cc:493] T 00000000000000000000000000000000 P 41668550618646a5800211fb2c076244 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:39.012282 31668 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 41668550618646a5800211fb2c076244 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:39.013104 31668 raft_consensus.cc:515] T 00000000000000000000000000000000 P 41668550618646a5800211fb2c076244 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "41668550618646a5800211fb2c076244" member_type: VOTER }
I20260812 06:18:39.013547 31668 leader_election.cc:304] T 00000000000000000000000000000000 P 41668550618646a5800211fb2c076244 [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: 41668550618646a5800211fb2c076244; no voters: 
I20260812 06:18:39.013911 31668 leader_election.cc:290] T 00000000000000000000000000000000 P 41668550618646a5800211fb2c076244 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:39.014070 31672 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 41668550618646a5800211fb2c076244 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:39.014345 31672 raft_consensus.cc:697] T 00000000000000000000000000000000 P 41668550618646a5800211fb2c076244 [term 1 LEADER]: Becoming Leader. State: Replica: 41668550618646a5800211fb2c076244, State: Running, Role: LEADER
I20260812 06:18:39.014762 31672 consensus_queue.cc:237] T 00000000000000000000000000000000 P 41668550618646a5800211fb2c076244 [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: "41668550618646a5800211fb2c076244" member_type: VOTER }
I20260812 06:18:39.014961 31668 sys_catalog.cc:565] T 00000000000000000000000000000000 P 41668550618646a5800211fb2c076244 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:39.016860 31674 sys_catalog.cc:455] T 00000000000000000000000000000000 P 41668550618646a5800211fb2c076244 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "41668550618646a5800211fb2c076244" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "41668550618646a5800211fb2c076244" member_type: VOTER } }
I20260812 06:18:39.017098 31674 sys_catalog.cc:458] T 00000000000000000000000000000000 P 41668550618646a5800211fb2c076244 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:39.017259 31566 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:39.016840 31676 sys_catalog.cc:455] T 00000000000000000000000000000000 P 41668550618646a5800211fb2c076244 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 41668550618646a5800211fb2c076244. Latest consensus state: current_term: 1 leader_uuid: "41668550618646a5800211fb2c076244" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "41668550618646a5800211fb2c076244" member_type: VOTER } }
I20260812 06:18:39.017343 31676 sys_catalog.cc:458] T 00000000000000000000000000000000 P 41668550618646a5800211fb2c076244 [sys.catalog]: This master's current role is: LEADER
W20260812 06:18:39.019714 31695 catalog_manager.cc:1594] T 00000000000000000000000000000000 P 41668550618646a5800211fb2c076244: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:18:39.019793 31695 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:18:39.020015 31698 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:39.020975 31698 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:39.025748 31698 catalog_manager.cc:1383] Generated new cluster ID: ccfba4f8d4fb4ce5bc6240059e7dca5f
I20260812 06:18:39.025820 31698 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:39.047935 31698 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:39.048830 31698 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:39.054248 31698 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 41668550618646a5800211fb2c076244: Generated new TSK 0
I20260812 06:18:39.054863 31698 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:39.082288 31566 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:39.085558 31704 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.085708 31705 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.085708 31707 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.085951 31566 server_base.cc:1061] running on GCE node
I20260812 06:18:39.086130 31566 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:39.086169 31566 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.086186 31566 hybrid_clock.cc:648] HybridClock initialized: now 1786515519086186 us; error 0 us; skew 500 ppm
I20260812 06:18:39.087169 31566 webserver.cc:533] Webserver started at http://127.30.211.129:35227/ using document root <none> and password file <none>
I20260812 06:18:39.087365 31566 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:39.087432 31566 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:39.087519 31566 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:39.087931 31566 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518923217-31566-0/minicluster-data/ts-0-root/instance:
uuid: "577be1f9d4cf48f1ae2a6b9b5cbc41e6"
format_stamp: "Formatted at 2026-08-12 06:18:39 on dist-test-slave-t3q3"
I20260812 06:18:39.089563 31566 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:39.090581 31715 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.090828 31566 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:39.090902 31566 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518923217-31566-0/minicluster-data/ts-0-root
uuid: "577be1f9d4cf48f1ae2a6b9b5cbc41e6"
format_stamp: "Formatted at 2026-08-12 06:18:39 on dist-test-slave-t3q3"
I20260812 06:18:39.090997 31566 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518923217-31566-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518923217-31566-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518923217-31566-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:39.097597 31566 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:39.098014 31566 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:39.098512 31566 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:39.099619 31566 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:39.099689 31566 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:39.099751 31566 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:39.099781 31566 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:39.107018 31566 rpc_server.cc:307] RPC server started. Bound to: 127.30.211.129:42597
I20260812 06:18:39.107053 31819 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.30.211.129:42597 every 8 connection(s)
I20260812 06:18:39.120134 31821 heartbeater.cc:344] Connected to a master server at 127.30.211.190:43023
I20260812 06:18:39.120383 31821 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:39.120822 31821 heartbeater.cc:507] Master 127.30.211.190:43023 requested a full tablet report, sending...
I20260812 06:18:39.122162 31611 ts_manager.cc:194] Registered new tserver with Master: 577be1f9d4cf48f1ae2a6b9b5cbc41e6 (127.30.211.129:42597)
I20260812 06:18:39.122288 31566 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.014619024s
I20260812 06:18:39.123485 31611 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:58146
I20260812 06:18:39.131731 31611 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:58156:
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:39.144940 31762 tablet_service.cc:1511] Processing CreateTablet for tablet 33b1581e33f74f34859a7765f91c980f (DEFAULT_TABLE table=heavy-update-compaction-test [id=da781b2dd2104842b1ba6b8b87da8ba8]), partition=
I20260812 06:18:39.145373 31762 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 33b1581e33f74f34859a7765f91c980f. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:39.147867 31844 tablet_bootstrap.cc:492] T 33b1581e33f74f34859a7765f91c980f P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Bootstrap starting.
I20260812 06:18:39.148808 31844 tablet_bootstrap.cc:654] T 33b1581e33f74f34859a7765f91c980f P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:39.150079 31844 tablet_bootstrap.cc:492] T 33b1581e33f74f34859a7765f91c980f P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: No bootstrap required, opened a new log
I20260812 06:18:39.150192 31844 ts_tablet_manager.cc:1403] T 33b1581e33f74f34859a7765f91c980f P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:39.150642 31844 raft_consensus.cc:359] T 33b1581e33f74f34859a7765f91c980f P 577be1f9d4cf48f1ae2a6b9b5cbc41e6 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "577be1f9d4cf48f1ae2a6b9b5cbc41e6" member_type: VOTER last_known_addr { host: "127.30.211.129" port: 42597 } }
I20260812 06:18:39.150744 31844 raft_consensus.cc:385] T 33b1581e33f74f34859a7765f91c980f P 577be1f9d4cf48f1ae2a6b9b5cbc41e6 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:39.150768 31844 raft_consensus.cc:740] T 33b1581e33f74f34859a7765f91c980f P 577be1f9d4cf48f1ae2a6b9b5cbc41e6 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 577be1f9d4cf48f1ae2a6b9b5cbc41e6, State: Initialized, Role: FOLLOWER
I20260812 06:18:39.150938 31844 consensus_queue.cc:260] T 33b1581e33f74f34859a7765f91c980f P 577be1f9d4cf48f1ae2a6b9b5cbc41e6 [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: "577be1f9d4cf48f1ae2a6b9b5cbc41e6" member_type: VOTER last_known_addr { host: "127.30.211.129" port: 42597 } }
I20260812 06:18:39.151011 31844 raft_consensus.cc:399] T 33b1581e33f74f34859a7765f91c980f P 577be1f9d4cf48f1ae2a6b9b5cbc41e6 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:39.151067 31844 raft_consensus.cc:493] T 33b1581e33f74f34859a7765f91c980f P 577be1f9d4cf48f1ae2a6b9b5cbc41e6 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:39.151117 31844 raft_consensus.cc:3060] T 33b1581e33f74f34859a7765f91c980f P 577be1f9d4cf48f1ae2a6b9b5cbc41e6 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:39.151885 31844 raft_consensus.cc:515] T 33b1581e33f74f34859a7765f91c980f P 577be1f9d4cf48f1ae2a6b9b5cbc41e6 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "577be1f9d4cf48f1ae2a6b9b5cbc41e6" member_type: VOTER last_known_addr { host: "127.30.211.129" port: 42597 } }
I20260812 06:18:39.152020 31844 leader_election.cc:304] T 33b1581e33f74f34859a7765f91c980f P 577be1f9d4cf48f1ae2a6b9b5cbc41e6 [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: 577be1f9d4cf48f1ae2a6b9b5cbc41e6; no voters: 
I20260812 06:18:39.152282 31844 leader_election.cc:290] T 33b1581e33f74f34859a7765f91c980f P 577be1f9d4cf48f1ae2a6b9b5cbc41e6 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:39.152392 31846 raft_consensus.cc:2804] T 33b1581e33f74f34859a7765f91c980f P 577be1f9d4cf48f1ae2a6b9b5cbc41e6 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:39.152648 31844 ts_tablet_manager.cc:1434] T 33b1581e33f74f34859a7765f91c980f P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:18:39.152624 31846 raft_consensus.cc:697] T 33b1581e33f74f34859a7765f91c980f P 577be1f9d4cf48f1ae2a6b9b5cbc41e6 [term 1 LEADER]: Becoming Leader. State: Replica: 577be1f9d4cf48f1ae2a6b9b5cbc41e6, State: Running, Role: LEADER
I20260812 06:18:39.152987 31821 heartbeater.cc:499] Master 127.30.211.190:43023 was elected leader, sending a full tablet report...
I20260812 06:18:39.152814 31846 consensus_queue.cc:237] T 33b1581e33f74f34859a7765f91c980f P 577be1f9d4cf48f1ae2a6b9b5cbc41e6 [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: "577be1f9d4cf48f1ae2a6b9b5cbc41e6" member_type: VOTER last_known_addr { host: "127.30.211.129" port: 42597 } }
I20260812 06:18:39.155990 31611 catalog_manager.cc:5719] T 33b1581e33f74f34859a7765f91c980f P 577be1f9d4cf48f1ae2a6b9b5cbc41e6 reported cstate change: term changed from 0 to 1, leader changed from <none> to 577be1f9d4cf48f1ae2a6b9b5cbc41e6 (127.30.211.129). New cstate: current_term: 1 leader_uuid: "577be1f9d4cf48f1ae2a6b9b5cbc41e6" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "577be1f9d4cf48f1ae2a6b9b5cbc41e6" member_type: VOTER last_known_addr { host: "127.30.211.129" port: 42597 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:39.224221 31566 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.063s	user 0.023s	sys 0.008s
I20260812 06:18:39.358086 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling FlushMRSOp(33b1581e33f74f34859a7765f91c980f): perf score=19.054940
I20260812 06:18:39.547549 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: FlushMRSOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.189s	user 0.148s	sys 0.032s Metrics: {"bytes_written":12717734,"cfile_init":1,"compiler_manager_pool.queue_time_us":198,"delete_count":0,"dirs.queue_time_us":378,"dirs.run_cpu_time_us":261,"dirs.run_wall_time_us":2592,"drs_written":1,"lbm_read_time_us":101,"lbm_reads_lt_1ms":4,"lbm_write_time_us":45735,"lbm_writes_lt_1ms":767,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":128,"threads_started":1,"update_count":1550}
I20260812 06:18:39.548996 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling LogGCOp(33b1581e33f74f34859a7765f91c980f): free 20743831 bytes of WAL
I20260812 06:18:39.549357 31721 log_reader.cc:385] T 33b1581e33f74f34859a7765f91c980f: removed 2 log segments from log reader
I20260812 06:18:39.549444 31721 log.cc:1079] T 33b1581e33f74f34859a7765f91c980f P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/33b1581e33f74f34859a7765f91c980f/wal-000000001 (ops 1-6)
I20260812 06:18:39.549532 31721 log.cc:1079] T 33b1581e33f74f34859a7765f91c980f P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/33b1581e33f74f34859a7765f91c980f/wal-000000002 (ops 7-11)
I20260812 06:18:39.555063 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: LogGCOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.006s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:18:39.555389 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling UndoDeltaBlockGCOp(33b1581e33f74f34859a7765f91c980f): 16411393 bytes on disk
I20260812 06:18:39.555969 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: UndoDeltaBlockGCOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":68,"lbm_reads_lt_1ms":4}
I20260812 06:18:39.556383 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f): perf score=2.188937
I20260812 06:18:39.585750 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.029s	user 0.002s	sys 0.015s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4235,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:39.586290 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f): perf score=2.188937
I20260812 06:18:39.599179 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.013s	user 0.003s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5007,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:39.599705 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling MajorDeltaCompactionOp(33b1581e33f74f34859a7765f91c980f): perf score=1.000000
I20260812 06:18:39.793601 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: MajorDeltaCompactionOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.194s	user 0.148s	sys 0.044s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774798,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":831,"lbm_read_time_us":12238,"lbm_reads_lt_1ms":569,"lbm_write_time_us":33277,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2176,"thread_start_us":319,"threads_started":5,"update_count":2500}
I20260812 06:18:39.794059 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f): perf score=10.126437
I20260812 06:18:39.841723 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.047s	user 0.025s	sys 0.016s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":18765,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:39.842254 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f): perf score=2.188937
I20260812 06:18:39.853055 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3948,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:39.853734 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling MajorDeltaCompactionOp(33b1581e33f74f34859a7765f91c980f): perf score=1.000000
I20260812 06:18:39.982858 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: MajorDeltaCompactionOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.129s	user 0.102s	sys 0.023s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"lbm_read_time_us":9122,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23860,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":2000}
I20260812 06:18:39.983377 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f): perf score=10.126437
I20260812 06:18:40.032390 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.049s	user 0.022s	sys 0.024s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":21000,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:40.032869 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f): perf score=2.188937
I20260812 06:18:40.043319 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3958,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:40.043926 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling MajorDeltaCompactionOp(33b1581e33f74f34859a7765f91c980f): perf score=1.000000
I20260812 06:18:40.171085 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: MajorDeltaCompactionOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.127s	user 0.090s	sys 0.037s 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":278,"lbm_read_time_us":9052,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25925,"lbm_writes_lt_1ms":443,"mutex_wait_us":38,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":37376,"update_count":2000}
I20260812 06:18:40.171702 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f): perf score=10.126437
I20260812 06:18:40.209774 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.038s	user 0.019s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15727,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:40.210209 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f): perf score=2.188937
I20260812 06:18:40.220775 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4199,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:40.221210 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling MajorDeltaCompactionOp(33b1581e33f74f34859a7765f91c980f): perf score=1.000000
I20260812 06:18:40.338742 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: MajorDeltaCompactionOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.117s	user 0.089s	sys 0.028s 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":263,"lbm_read_time_us":9216,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22685,"lbm_writes_lt_1ms":443,"mutex_wait_us":51,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":32128,"update_count":2000}
I20260812 06:18:40.339335 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f): perf score=10.126437
I20260812 06:18:40.386554 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.047s	user 0.026s	sys 0.018s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16817,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:40.387127 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f): perf score=2.188937
I20260812 06:18:40.397619 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4069,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:40.398120 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling MajorDeltaCompactionOp(33b1581e33f74f34859a7765f91c980f): perf score=1.000000
I20260812 06:18:40.547828 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: MajorDeltaCompactionOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.150s	user 0.110s	sys 0.034s 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":587,"lbm_read_time_us":10975,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24408,"lbm_writes_lt_1ms":443,"mutex_wait_us":62,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:18:40.548374 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f): perf score=11.118625
I20260812 06:18:40.586135 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.038s	user 0.027s	sys 0.008s Metrics: {"bytes_written":13086952,"delete_count":0,"lbm_write_time_us":16028,"lbm_writes_lt_1ms":322,"reinsert_count":0,"update_count":1595}
I20260812 06:18:40.586612 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f): perf score=2.188937
I20260812 06:18:40.597846 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.011s	user 0.007s	sys 0.001s Metrics: {"bytes_written":3733434,"delete_count":0,"lbm_write_time_us":3591,"lbm_writes_lt_1ms":94,"reinsert_count":0,"update_count":455}
I20260812 06:18:40.598285 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f): perf score=2.188937
I20260812 06:18:40.607744 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.009s	user 0.006s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3562,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:40.608244 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling MajorDeltaCompactionOp(33b1581e33f74f34859a7765f91c980f): perf score=1.000000
I20260812 06:18:40.779354 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: MajorDeltaCompactionOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.171s	user 0.133s	sys 0.034s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774791,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":205,"lbm_read_time_us":11984,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29838,"lbm_writes_lt_1ms":543,"mutex_wait_us":92,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2500}
I20260812 06:18:40.784521 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f): perf score=12.110812
I20260812 06:18:40.824312 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.040s	user 0.022s	sys 0.017s Metrics: {"bytes_written":13784351,"delete_count":0,"lbm_write_time_us":17014,"lbm_writes_lt_1ms":339,"reinsert_count":0,"update_count":1680}
I20260812 06:18:40.824942 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f): perf score=1.196750
I20260812 06:18:40.840744 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.016s	user 0.002s	sys 0.006s Metrics: {"bytes_written":3036009,"delete_count":0,"lbm_write_time_us":3117,"lbm_writes_lt_1ms":77,"reinsert_count":0,"update_count":370}
I20260812 06:18:40.841230 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f): perf score=2.188937
I20260812 06:18:40.850670 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.009s	user 0.002s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3525,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:40.851140 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling FlushMRSOp(33b1581e33f74f34859a7765f91c980f): perf score=1.000000
I20260812 06:18:40.885996 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: FlushMRSOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.035s	user 0.030s	sys 0.003s Metrics: {"bytes_written":1275443,"cfile_init":1,"dirs.queue_time_us":78,"dirs.run_cpu_time_us":257,"dirs.run_wall_time_us":1222,"drs_written":1,"lbm_read_time_us":44,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2080,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:40.886830 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling LogGCOp(33b1581e33f74f34859a7765f91c980f): free 121006480 bytes of WAL
I20260812 06:18:40.887063 31721 log_reader.cc:385] T 33b1581e33f74f34859a7765f91c980f: removed 12 log segments from log reader
I20260812 06:18:40.887110 31721 log.cc:1079] T 33b1581e33f74f34859a7765f91c980f P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/33b1581e33f74f34859a7765f91c980f/wal-000000003 (ops 12-16)
I20260812 06:18:40.887138 31721 log.cc:1079] T 33b1581e33f74f34859a7765f91c980f P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/33b1581e33f74f34859a7765f91c980f/wal-000000004 (ops 17-21)
I20260812 06:18:40.887197 31721 log.cc:1079] T 33b1581e33f74f34859a7765f91c980f P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/33b1581e33f74f34859a7765f91c980f/wal-000000005 (ops 22-26)
I20260812 06:18:40.887238 31721 log.cc:1079] T 33b1581e33f74f34859a7765f91c980f P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/33b1581e33f74f34859a7765f91c980f/wal-000000006 (ops 27-30)
I20260812 06:18:40.887281 31721 log.cc:1079] T 33b1581e33f74f34859a7765f91c980f P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/33b1581e33f74f34859a7765f91c980f/wal-000000007 (ops 31-35)
I20260812 06:18:40.887337 31721 log.cc:1079] T 33b1581e33f74f34859a7765f91c980f P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/33b1581e33f74f34859a7765f91c980f/wal-000000008 (ops 36-40)
I20260812 06:18:40.887394 31721 log.cc:1079] T 33b1581e33f74f34859a7765f91c980f P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/33b1581e33f74f34859a7765f91c980f/wal-000000009 (ops 41-45)
I20260812 06:18:40.887437 31721 log.cc:1079] T 33b1581e33f74f34859a7765f91c980f P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/33b1581e33f74f34859a7765f91c980f/wal-000000010 (ops 46-50)
I20260812 06:18:40.887475 31721 log.cc:1079] T 33b1581e33f74f34859a7765f91c980f P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/33b1581e33f74f34859a7765f91c980f/wal-000000011 (ops 51-55)
I20260812 06:18:40.887513 31721 log.cc:1079] T 33b1581e33f74f34859a7765f91c980f P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/33b1581e33f74f34859a7765f91c980f/wal-000000012 (ops 56-60)
I20260812 06:18:40.887552 31721 log.cc:1079] T 33b1581e33f74f34859a7765f91c980f P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/33b1581e33f74f34859a7765f91c980f/wal-000000013 (ops 61-65)
I20260812 06:18:40.887589 31721 log.cc:1079] T 33b1581e33f74f34859a7765f91c980f P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/33b1581e33f74f34859a7765f91c980f/wal-000000014 (ops 66-70)
I20260812 06:18:40.916626 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: LogGCOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.030s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:18:40.917137 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f): perf score=3.181125
I20260812 06:18:40.935242 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.018s	user 0.011s	sys 0.002s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":4970,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:40.935701 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling UndoDeltaBlockGCOp(33b1581e33f74f34859a7765f91c980f): 483 bytes on disk
I20260812 06:18:40.936154 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: UndoDeltaBlockGCOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4}
I20260812 06:18:40.936614 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f): perf score=2.188937
I20260812 06:18:40.946355 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3744,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:40.946777 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling MajorDeltaCompactionOp(33b1581e33f74f34859a7765f91c980f): perf score=1.000000
I20260812 06:18:41.175628 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: MajorDeltaCompactionOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.229s	user 0.160s	sys 0.069s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979816,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":71,"lbm_read_time_us":16929,"lbm_reads_lt_1ms":775,"lbm_write_time_us":41594,"lbm_writes_lt_1ms":743,"mutex_wait_us":1,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":2560,"thread_start_us":81,"threads_started":1,"update_count":3500}
I20260812 06:18:41.176376 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f): perf score=14.095187
I20260812 06:18:41.227968 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.049s	user 0.026s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22546,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:41.228542 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f): perf score=2.188937
I20260812 06:18:41.241883 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.013s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4718,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:41.242321 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling MajorDeltaCompactionOp(33b1581e33f74f34859a7765f91c980f): perf score=1.000000
I20260812 06:18:41.415220 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: MajorDeltaCompactionOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.173s	user 0.106s	sys 0.064s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":242,"lbm_read_time_us":12043,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29749,"lbm_writes_lt_1ms":543,"mutex_wait_us":43,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2500}
I20260812 06:18:41.415776 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f): perf score=14.095187
I20260812 06:18:41.480173 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.064s	user 0.045s	sys 0.011s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20996,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:41.480697 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f): perf score=2.188937
I20260812 06:18:41.490883 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3982,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:41.491288 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling MajorDeltaCompactionOp(33b1581e33f74f34859a7765f91c980f): perf score=1.000000
I20260812 06:18:41.673388 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: MajorDeltaCompactionOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.182s	user 0.138s	sys 0.043s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1158,"lbm_read_time_us":13619,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30574,"lbm_writes_lt_1ms":543,"mutex_wait_us":350,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:18:41.674062 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f): perf score=10.126437
I20260812 06:18:41.706409 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.032s	user 0.020s	sys 0.009s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14012,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:41.706960 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f): perf score=2.188937
I20260812 06:18:41.721237 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4916,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:41.721714 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling MajorDeltaCompactionOp(33b1581e33f74f34859a7765f91c980f): perf score=1.000000
I20260812 06:18:41.867964 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: MajorDeltaCompactionOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.146s	user 0.099s	sys 0.041s 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":1066,"lbm_read_time_us":8921,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24635,"lbm_writes_lt_1ms":443,"mutex_wait_us":51,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12928,"update_count":2000}
I20260812 06:18:41.868526 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f): perf score=10.126437
I20260812 06:18:41.904187 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.035s	user 0.028s	sys 0.007s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":15168,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:41.904659 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f): perf score=2.188937
I20260812 06:18:41.919577 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5655,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:41.920207 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling MajorDeltaCompactionOp(33b1581e33f74f34859a7765f91c980f): perf score=1.000000
I20260812 06:18:42.045308 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: MajorDeltaCompactionOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.125s	user 0.104s	sys 0.021s 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":344,"lbm_read_time_us":10281,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22439,"lbm_writes_lt_1ms":443,"mutex_wait_us":48,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:42.046066 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f): perf score=10.126437
I20260812 06:18:42.089758 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.043s	user 0.033s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18956,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:42.090328 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling MajorDeltaCompactionOp(33b1581e33f74f34859a7765f91c980f): perf score=1.000000
I20260812 06:18:42.200323 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: MajorDeltaCompactionOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.110s	user 0.094s	sys 0.016s 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":255,"lbm_read_time_us":6592,"lbm_reads_lt_1ms":363,"lbm_write_time_us":21728,"lbm_writes_lt_1ms":343,"mutex_wait_us":26,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":13824,"update_count":1500}
I20260812 06:18:42.200999 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f): perf score=10.126437
I20260812 06:18:42.249399 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.048s	user 0.023s	sys 0.024s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":21512,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:42.249948 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f): perf score=2.188937
I20260812 06:18:42.261545 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3985,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:42.262072 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling MajorDeltaCompactionOp(33b1581e33f74f34859a7765f91c980f): perf score=1.000000
I20260812 06:18:42.402419 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: MajorDeltaCompactionOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.140s	user 0.096s	sys 0.044s 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":912,"lbm_read_time_us":9429,"lbm_reads_lt_1ms":472,"lbm_write_time_us":30331,"lbm_writes_lt_1ms":443,"mutex_wait_us":376,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:18:42.406107 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f): perf score=10.126437
I20260812 06:18:42.449491 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.043s	user 0.033s	sys 0.007s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":18457,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:42.449980 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f): perf score=2.188937
I20260812 06:18:42.461345 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4063,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:42.462044 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling FlushMRSOp(33b1581e33f74f34859a7765f91c980f): perf score=1.000000
I20260812 06:18:42.490365 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: FlushMRSOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.028s	user 0.027s	sys 0.000s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":71,"dirs.run_cpu_time_us":266,"dirs.run_wall_time_us":1534,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1740,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:42.491078 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling LogGCOp(33b1581e33f74f34859a7765f91c980f): free 132571336 bytes of WAL
I20260812 06:18:42.491312 31721 log_reader.cc:385] T 33b1581e33f74f34859a7765f91c980f: removed 13 log segments from log reader
I20260812 06:18:42.491377 31721 log.cc:1079] T 33b1581e33f74f34859a7765f91c980f P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/33b1581e33f74f34859a7765f91c980f/wal-000000015 (ops 71-75)
I20260812 06:18:42.491434 31721 log.cc:1079] T 33b1581e33f74f34859a7765f91c980f P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/33b1581e33f74f34859a7765f91c980f/wal-000000016 (ops 76-80)
I20260812 06:18:42.491518 31721 log.cc:1079] T 33b1581e33f74f34859a7765f91c980f P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/33b1581e33f74f34859a7765f91c980f/wal-000000017 (ops 81-85)
I20260812 06:18:42.491590 31721 log.cc:1079] T 33b1581e33f74f34859a7765f91c980f P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/33b1581e33f74f34859a7765f91c980f/wal-000000018 (ops 86-90)
I20260812 06:18:42.491633 31721 log.cc:1079] T 33b1581e33f74f34859a7765f91c980f P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/33b1581e33f74f34859a7765f91c980f/wal-000000019 (ops 91-95)
I20260812 06:18:42.491671 31721 log.cc:1079] T 33b1581e33f74f34859a7765f91c980f P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/33b1581e33f74f34859a7765f91c980f/wal-000000020 (ops 96-100)
I20260812 06:18:42.491762 31721 log.cc:1079] T 33b1581e33f74f34859a7765f91c980f P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/33b1581e33f74f34859a7765f91c980f/wal-000000021 (ops 101-105)
I20260812 06:18:42.491803 31721 log.cc:1079] T 33b1581e33f74f34859a7765f91c980f P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/33b1581e33f74f34859a7765f91c980f/wal-000000022 (ops 106-110)
I20260812 06:18:42.491840 31721 log.cc:1079] T 33b1581e33f74f34859a7765f91c980f P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/33b1581e33f74f34859a7765f91c980f/wal-000000023 (ops 111-114)
I20260812 06:18:42.491878 31721 log.cc:1079] T 33b1581e33f74f34859a7765f91c980f P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/33b1581e33f74f34859a7765f91c980f/wal-000000024 (ops 115-119)
I20260812 06:18:42.491916 31721 log.cc:1079] T 33b1581e33f74f34859a7765f91c980f P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/33b1581e33f74f34859a7765f91c980f/wal-000000025 (ops 120-124)
I20260812 06:18:42.491954 31721 log.cc:1079] T 33b1581e33f74f34859a7765f91c980f P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/33b1581e33f74f34859a7765f91c980f/wal-000000026 (ops 125-128)
I20260812 06:18:42.491993 31721 log.cc:1079] T 33b1581e33f74f34859a7765f91c980f P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/33b1581e33f74f34859a7765f91c980f/wal-000000027 (ops 129-133)
I20260812 06:18:42.522776 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: LogGCOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.032s	user 0.002s	sys 0.027s Metrics: {}
I20260812 06:18:42.523253 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f): perf score=5.165500
I20260812 06:18:42.541450 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.018s	user 0.013s	sys 0.004s Metrics: {"bytes_written":7056402,"delete_count":0,"lbm_write_time_us":7455,"lbm_writes_lt_1ms":175,"reinsert_count":0,"update_count":860}
I20260812 06:18:42.542163 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f): perf score=1.000000
I20260812 06:18:42.551450 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.009s	user 0.005s	sys 0.000s Metrics: {"bytes_written":1148852,"delete_count":0,"lbm_write_time_us":1855,"lbm_writes_lt_1ms":31,"reinsert_count":0,"update_count":140}
I20260812 06:18:42.551991 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling UndoDeltaBlockGCOp(33b1581e33f74f34859a7765f91c980f): 482 bytes on disk
I20260812 06:18:42.552644 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: UndoDeltaBlockGCOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":111,"lbm_reads_lt_1ms":4}
I20260812 06:18:42.553237 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling MajorDeltaCompactionOp(33b1581e33f74f34859a7765f91c980f): perf score=1.000000
I20260812 06:18:42.726016 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: MajorDeltaCompactionOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.173s	user 0.111s	sys 0.060s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":521,"lbm_read_time_us":11371,"lbm_reads_lt_1ms":666,"lbm_write_time_us":37561,"lbm_writes_lt_1ms":643,"mutex_wait_us":23,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":12800,"thread_start_us":76,"threads_started":1,"update_count":3000}
I20260812 06:18:42.727803 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f): perf score=14.095187
I20260812 06:18:42.784014 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.056s	user 0.026s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23007,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:42.784638 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f): perf score=2.188937
I20260812 06:18:42.804347 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.019s	user 0.009s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6536,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:42.804811 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling MajorDeltaCompactionOp(33b1581e33f74f34859a7765f91c980f): perf score=1.000000
I20260812 06:18:42.959794 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: MajorDeltaCompactionOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.155s	user 0.105s	sys 0.037s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":640,"lbm_read_time_us":9356,"lbm_reads_lt_1ms":564,"lbm_write_time_us":28139,"lbm_writes_lt_1ms":543,"mutex_wait_us":302,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":55936,"update_count":2500}
I20260812 06:18:42.960492 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f): perf score=14.095187
I20260812 06:18:43.017766 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.057s	user 0.025s	sys 0.027s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23650,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:43.018306 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f): perf score=2.188937
I20260812 06:18:43.030864 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4283,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.031435 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling MajorDeltaCompactionOp(33b1581e33f74f34859a7765f91c980f): perf score=1.000000
I20260812 06:18:43.183549 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: MajorDeltaCompactionOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.152s	user 0.122s	sys 0.021s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":913,"lbm_read_time_us":10391,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28849,"lbm_writes_lt_1ms":543,"mutex_wait_us":145,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":25088,"update_count":2500}
I20260812 06:18:43.184286 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f): perf score=14.095187
I20260812 06:18:43.237471 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.053s	user 0.039s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24126,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:43.238001 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f): perf score=2.188937
I20260812 06:18:43.250577 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.012s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4286,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.251201 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling MajorDeltaCompactionOp(33b1581e33f74f34859a7765f91c980f): perf score=1.000000
I20260812 06:18:43.417117 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: MajorDeltaCompactionOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.166s	user 0.110s	sys 0.043s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":307,"lbm_read_time_us":9647,"lbm_reads_lt_1ms":568,"lbm_write_time_us":33033,"lbm_writes_lt_1ms":543,"mutex_wait_us":29,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":160256,"update_count":2500}
I20260812 06:18:43.417797 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f): perf score=14.095187
I20260812 06:18:43.471465 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.054s	user 0.028s	sys 0.021s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23152,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:43.472123 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f): perf score=2.188937
I20260812 06:18:43.483914 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.012s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4299,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.484578 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling MajorDeltaCompactionOp(33b1581e33f74f34859a7765f91c980f): perf score=1.000000
I20260812 06:18:43.652860 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: MajorDeltaCompactionOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.168s	user 0.110s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":247,"lbm_read_time_us":11763,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32276,"lbm_writes_lt_1ms":543,"mutex_wait_us":7,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4480,"update_count":2500}
I20260812 06:18:43.653896 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f): perf score=12.110812
I20260812 06:18:43.717676 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.064s	user 0.023s	sys 0.032s Metrics: {"bytes_written":13702313,"delete_count":0,"lbm_write_time_us":27036,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":334,"reinsert_count":0,"spinlock_wait_cycles":2944,"update_count":1670}
I20260812 06:18:43.718374 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f): perf score=1.196750
I20260812 06:18:43.731428 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.013s	user 0.000s	sys 0.007s Metrics: {"bytes_written":3118059,"delete_count":0,"lbm_write_time_us":3190,"lbm_writes_lt_1ms":79,"reinsert_count":0,"update_count":380}
I20260812 06:18:43.732160 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f): perf score=2.188937
I20260812 06:18:43.744272 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.012s	user 0.011s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4328,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:43.745049 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling MajorDeltaCompactionOp(33b1581e33f74f34859a7765f91c980f): perf score=1.000000
I20260812 06:18:43.942937 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: MajorDeltaCompactionOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.198s	user 0.124s	sys 0.068s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774777,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1014,"lbm_read_time_us":13892,"lbm_reads_lt_1ms":573,"lbm_write_time_us":35718,"lbm_writes_lt_1ms":543,"mutex_wait_us":299,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11264,"update_count":2500}
I20260812 06:18:43.943627 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f): perf score=14.095187
I20260812 06:18:44.003419 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.060s	user 0.032s	sys 0.019s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":26771,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":400,"reinsert_count":0,"update_count":2000}
I20260812 06:18:44.004002 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f): perf score=2.188937
I20260812 06:18:44.015152 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4212,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.016252 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling FlushMRSOp(33b1581e33f74f34859a7765f91c980f): perf score=1.000000
I20260812 06:18:44.055122 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: FlushMRSOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.039s	user 0.036s	sys 0.000s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":105,"dirs.run_cpu_time_us":347,"dirs.run_wall_time_us":1532,"drs_written":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2474,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:18:44.055933 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling LogGCOp(33b1581e33f74f34859a7765f91c980f): free 129320795 bytes of WAL
I20260812 06:18:44.056290 31721 log_reader.cc:385] T 33b1581e33f74f34859a7765f91c980f: removed 13 log segments from log reader
I20260812 06:18:44.056358 31721 log.cc:1079] T 33b1581e33f74f34859a7765f91c980f P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/33b1581e33f74f34859a7765f91c980f/wal-000000028 (ops 134-138)
I20260812 06:18:44.056401 31721 log.cc:1079] T 33b1581e33f74f34859a7765f91c980f P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/33b1581e33f74f34859a7765f91c980f/wal-000000029 (ops 139-143)
I20260812 06:18:44.056430 31721 log.cc:1079] T 33b1581e33f74f34859a7765f91c980f P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/33b1581e33f74f34859a7765f91c980f/wal-000000030 (ops 144-148)
I20260812 06:18:44.056457 31721 log.cc:1079] T 33b1581e33f74f34859a7765f91c980f P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/33b1581e33f74f34859a7765f91c980f/wal-000000031 (ops 149-152)
I20260812 06:18:44.056490 31721 log.cc:1079] T 33b1581e33f74f34859a7765f91c980f P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/33b1581e33f74f34859a7765f91c980f/wal-000000032 (ops 153-157)
I20260812 06:18:44.056519 31721 log.cc:1079] T 33b1581e33f74f34859a7765f91c980f P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/33b1581e33f74f34859a7765f91c980f/wal-000000033 (ops 158-162)
I20260812 06:18:44.056542 31721 log.cc:1079] T 33b1581e33f74f34859a7765f91c980f P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/33b1581e33f74f34859a7765f91c980f/wal-000000034 (ops 163-167)
I20260812 06:18:44.056563 31721 log.cc:1079] T 33b1581e33f74f34859a7765f91c980f P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/33b1581e33f74f34859a7765f91c980f/wal-000000035 (ops 168-172)
I20260812 06:18:44.056595 31721 log.cc:1079] T 33b1581e33f74f34859a7765f91c980f P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/33b1581e33f74f34859a7765f91c980f/wal-000000036 (ops 173-176)
I20260812 06:18:44.056629 31721 log.cc:1079] T 33b1581e33f74f34859a7765f91c980f P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/33b1581e33f74f34859a7765f91c980f/wal-000000037 (ops 177-181)
I20260812 06:18:44.056665 31721 log.cc:1079] T 33b1581e33f74f34859a7765f91c980f P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/33b1581e33f74f34859a7765f91c980f/wal-000000038 (ops 182-186)
I20260812 06:18:44.056699 31721 log.cc:1079] T 33b1581e33f74f34859a7765f91c980f P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/33b1581e33f74f34859a7765f91c980f/wal-000000039 (ops 187-191)
I20260812 06:18:44.056730 31721 log.cc:1079] T 33b1581e33f74f34859a7765f91c980f P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/33b1581e33f74f34859a7765f91c980f/wal-000000040 (ops 192-196)
I20260812 06:18:44.091507 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: LogGCOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.035s	user 0.004s	sys 0.028s Metrics: {}
I20260812 06:18:44.092144 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling UndoDeltaBlockGCOp(33b1581e33f74f34859a7765f91c980f): 492 bytes on disk
I20260812 06:18:44.092752 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: UndoDeltaBlockGCOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":98,"lbm_reads_lt_1ms":4}
I20260812 06:18:44.093420 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f): perf score=2.188937
I20260812 06:18:44.110687 31566 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.886s	user 1.836s	sys 0.094s
I20260812 06:18:44.112524 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.019s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4636,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.113039 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f): perf score=2.188937
I20260812 06:18:44.125186 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: FlushDeltaMemStoresOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4862,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.125681 31830 maintenance_manager.cc:419] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: Scheduling MajorDeltaCompactionOp(33b1581e33f74f34859a7765f91c980f): perf score=1.000000
I20260812 06:18:44.200620 31566 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.089s	user 0.003s	sys 0.000s
I20260812 06:18:44.201354 31566 tablet_server.cc:179] TabletServer@127.30.211.129:0 shutting down...
I20260812 06:18:44.297727 31721 maintenance_manager.cc:643] P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: MajorDeltaCompactionOp(33b1581e33f74f34859a7765f91c980f) complete. Timing: real 0.172s	user 0.132s	sys 0.040s Metrics: {"cfile_cache_hit":205,"cfile_cache_hit_bytes":8292453,"cfile_cache_miss":529,"cfile_cache_miss_bytes":24687298,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":874,"lbm_read_time_us":10890,"lbm_reads_lt_1ms":561,"lbm_write_time_us":34110,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":28544,"thread_start_us":84,"threads_started":1,"update_count":3500}
I20260812 06:18:44.299119 31566 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:44.299539 31566 tablet_replica.cc:333] T 33b1581e33f74f34859a7765f91c980f P 577be1f9d4cf48f1ae2a6b9b5cbc41e6: stopping tablet replica
I20260812 06:18:44.299785 31566 raft_consensus.cc:2243] T 33b1581e33f74f34859a7765f91c980f P 577be1f9d4cf48f1ae2a6b9b5cbc41e6 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:44.300043 31566 raft_consensus.cc:2272] T 33b1581e33f74f34859a7765f91c980f P 577be1f9d4cf48f1ae2a6b9b5cbc41e6 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:44.315582 31566 tablet_server.cc:196] TabletServer@127.30.211.129:0 shutdown complete.
I20260812 06:18:44.361778 31566 master.cc:562] Master@127.30.211.190:43023 shutting down...
I20260812 06:18:44.366189 31566 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 41668550618646a5800211fb2c076244 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:44.366415 31566 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 41668550618646a5800211fb2c076244 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:44.366523 31566 tablet_replica.cc:333] T 00000000000000000000000000000000 P 41668550618646a5800211fb2c076244: stopping tablet replica
I20260812 06:18:44.379194 31566 master.cc:584] Master@127.30.211.190:43023 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5535 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:44.469640 31566 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.30.211.190:43787
I20260812 06:18:44.470067 31566 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:44.472721 31875 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:44.472770 31872 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:44.472821 31566 server_base.cc:1061] running on GCE node
W20260812 06:18:44.473009 31873 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:44.473245 31566 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:44.473289 31566 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:44.473304 31566 hybrid_clock.cc:648] HybridClock initialized: now 1786515524473304 us; error 0 us; skew 500 ppm
I20260812 06:18:44.474153 31566 webserver.cc:533] Webserver started at http://127.30.211.190:43971/ using document root <none> and password file <none>
I20260812 06:18:44.474335 31566 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:44.474376 31566 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:44.474429 31566 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:44.474764 31566 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518923217-31566-0/minicluster-data/master-0-root/instance:
uuid: "eb5c4ccdd5a346aa86bc74194bf072ea"
format_stamp: "Formatted at 2026-08-12 06:18:44 on dist-test-slave-t3q3"
I20260812 06:18:44.476294 31566 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:44.477176 31884 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:44.477422 31566 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:44.477487 31566 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518923217-31566-0/minicluster-data/master-0-root
uuid: "eb5c4ccdd5a346aa86bc74194bf072ea"
format_stamp: "Formatted at 2026-08-12 06:18:44 on dist-test-slave-t3q3"
I20260812 06:18:44.477545 31566 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518923217-31566-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518923217-31566-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518923217-31566-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:44.485240 31566 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:44.485551 31566 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:44.490278 31566 rpc_server.cc:307] RPC server started. Bound to: 127.30.211.190:43787
I20260812 06:18:44.494187 31966 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.30.211.190:43787 every 8 connection(s)
I20260812 06:18:44.495568 31967 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:44.504204 31967 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P eb5c4ccdd5a346aa86bc74194bf072ea: Bootstrap starting.
I20260812 06:18:44.505054 31967 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P eb5c4ccdd5a346aa86bc74194bf072ea: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:44.506198 31967 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P eb5c4ccdd5a346aa86bc74194bf072ea: No bootstrap required, opened a new log
I20260812 06:18:44.506577 31967 raft_consensus.cc:359] T 00000000000000000000000000000000 P eb5c4ccdd5a346aa86bc74194bf072ea [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "eb5c4ccdd5a346aa86bc74194bf072ea" member_type: VOTER }
I20260812 06:18:44.506668 31967 raft_consensus.cc:385] T 00000000000000000000000000000000 P eb5c4ccdd5a346aa86bc74194bf072ea [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:44.506692 31967 raft_consensus.cc:740] T 00000000000000000000000000000000 P eb5c4ccdd5a346aa86bc74194bf072ea [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: eb5c4ccdd5a346aa86bc74194bf072ea, State: Initialized, Role: FOLLOWER
I20260812 06:18:44.506804 31967 consensus_queue.cc:260] T 00000000000000000000000000000000 P eb5c4ccdd5a346aa86bc74194bf072ea [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: "eb5c4ccdd5a346aa86bc74194bf072ea" member_type: VOTER }
I20260812 06:18:44.506867 31967 raft_consensus.cc:399] T 00000000000000000000000000000000 P eb5c4ccdd5a346aa86bc74194bf072ea [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:44.506891 31967 raft_consensus.cc:493] T 00000000000000000000000000000000 P eb5c4ccdd5a346aa86bc74194bf072ea [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:44.506924 31967 raft_consensus.cc:3060] T 00000000000000000000000000000000 P eb5c4ccdd5a346aa86bc74194bf072ea [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:44.507613 31967 raft_consensus.cc:515] T 00000000000000000000000000000000 P eb5c4ccdd5a346aa86bc74194bf072ea [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "eb5c4ccdd5a346aa86bc74194bf072ea" member_type: VOTER }
I20260812 06:18:44.507794 31967 leader_election.cc:304] T 00000000000000000000000000000000 P eb5c4ccdd5a346aa86bc74194bf072ea [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: eb5c4ccdd5a346aa86bc74194bf072ea; no voters: 
I20260812 06:18:44.508010 31967 leader_election.cc:290] T 00000000000000000000000000000000 P eb5c4ccdd5a346aa86bc74194bf072ea [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:44.508210 31973 raft_consensus.cc:2804] T 00000000000000000000000000000000 P eb5c4ccdd5a346aa86bc74194bf072ea [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:44.508455 31973 raft_consensus.cc:697] T 00000000000000000000000000000000 P eb5c4ccdd5a346aa86bc74194bf072ea [term 1 LEADER]: Becoming Leader. State: Replica: eb5c4ccdd5a346aa86bc74194bf072ea, State: Running, Role: LEADER
I20260812 06:18:44.508637 31967 sys_catalog.cc:565] T 00000000000000000000000000000000 P eb5c4ccdd5a346aa86bc74194bf072ea [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:44.508605 31973 consensus_queue.cc:237] T 00000000000000000000000000000000 P eb5c4ccdd5a346aa86bc74194bf072ea [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: "eb5c4ccdd5a346aa86bc74194bf072ea" member_type: VOTER }
I20260812 06:18:44.509143 31974 sys_catalog.cc:455] T 00000000000000000000000000000000 P eb5c4ccdd5a346aa86bc74194bf072ea [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "eb5c4ccdd5a346aa86bc74194bf072ea" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "eb5c4ccdd5a346aa86bc74194bf072ea" member_type: VOTER } }
I20260812 06:18:44.509259 31974 sys_catalog.cc:458] T 00000000000000000000000000000000 P eb5c4ccdd5a346aa86bc74194bf072ea [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:44.509367 31975 sys_catalog.cc:455] T 00000000000000000000000000000000 P eb5c4ccdd5a346aa86bc74194bf072ea [sys.catalog]: SysCatalogTable state changed. Reason: New leader eb5c4ccdd5a346aa86bc74194bf072ea. Latest consensus state: current_term: 1 leader_uuid: "eb5c4ccdd5a346aa86bc74194bf072ea" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "eb5c4ccdd5a346aa86bc74194bf072ea" member_type: VOTER } }
I20260812 06:18:44.509514 31975 sys_catalog.cc:458] T 00000000000000000000000000000000 P eb5c4ccdd5a346aa86bc74194bf072ea [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:44.509904 31982 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:44.510572 31982 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:44.510742 31566 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:44.512566 31982 catalog_manager.cc:1383] Generated new cluster ID: c29c2af69b7b468f822c604264831251
I20260812 06:18:44.512647 31982 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:44.531397 31982 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:44.532014 31982 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:44.539157 31982 catalog_manager.cc:6092] T 00000000000000000000000000000000 P eb5c4ccdd5a346aa86bc74194bf072ea: Generated new TSK 0
I20260812 06:18:44.539383 31982 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:44.543406 31566 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:44.545887 32005 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:44.545914 32011 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:44.545917 31566 server_base.cc:1061] running on GCE node
W20260812 06:18:44.545918 32007 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:44.546445 31566 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:44.546525 31566 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:44.546561 31566 hybrid_clock.cc:648] HybridClock initialized: now 1786515524546560 us; error 0 us; skew 500 ppm
I20260812 06:18:44.547561 31566 webserver.cc:533] Webserver started at http://127.30.211.129:40549/ using document root <none> and password file <none>
I20260812 06:18:44.547791 31566 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:44.547875 31566 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:44.547966 31566 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:44.548449 31566 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518923217-31566-0/minicluster-data/ts-0-root/instance:
uuid: "d2afc49f513f429cbd2f8792faeba212"
format_stamp: "Formatted at 2026-08-12 06:18:44 on dist-test-slave-t3q3"
I20260812 06:18:44.550194 31566 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:18:44.551281 32025 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:44.551554 31566 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:44.551674 31566 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518923217-31566-0/minicluster-data/ts-0-root
uuid: "d2afc49f513f429cbd2f8792faeba212"
format_stamp: "Formatted at 2026-08-12 06:18:44 on dist-test-slave-t3q3"
I20260812 06:18:44.551776 31566 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518923217-31566-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518923217-31566-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518923217-31566-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:44.562146 31566 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:44.562661 31566 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:44.563032 31566 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:44.563607 31566 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:44.563679 31566 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:44.563742 31566 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:44.563777 31566 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:44.568519 31566 rpc_server.cc:307] RPC server started. Bound to: 127.30.211.129:43793
I20260812 06:18:44.568614 32119 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.30.211.129:43793 every 8 connection(s)
I20260812 06:18:44.579449 32122 heartbeater.cc:344] Connected to a master server at 127.30.211.190:43787
I20260812 06:18:44.579586 32122 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:44.579834 32122 heartbeater.cc:507] Master 127.30.211.190:43787 requested a full tablet report, sending...
I20260812 06:18:44.580672 31916 ts_manager.cc:194] Registered new tserver with Master: d2afc49f513f429cbd2f8792faeba212 (127.30.211.129:43793)
I20260812 06:18:44.581519 31916 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:43820
I20260812 06:18:44.581614 31566 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.01256798s
I20260812 06:18:44.589821 31916 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:43822:
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:44.599455 32063 tablet_service.cc:1511] Processing CreateTablet for tablet 8ce587f6acf5408d93fc1e2e2021b144 (DEFAULT_TABLE table=heavy-update-compaction-test [id=c091a9fe5cc24913bb48960515d5f3af]), partition=
I20260812 06:18:44.599799 32063 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 8ce587f6acf5408d93fc1e2e2021b144. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:44.602275 32135 tablet_bootstrap.cc:492] T 8ce587f6acf5408d93fc1e2e2021b144 P d2afc49f513f429cbd2f8792faeba212: Bootstrap starting.
I20260812 06:18:44.603204 32135 tablet_bootstrap.cc:654] T 8ce587f6acf5408d93fc1e2e2021b144 P d2afc49f513f429cbd2f8792faeba212: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:44.604473 32135 tablet_bootstrap.cc:492] T 8ce587f6acf5408d93fc1e2e2021b144 P d2afc49f513f429cbd2f8792faeba212: No bootstrap required, opened a new log
I20260812 06:18:44.604583 32135 ts_tablet_manager.cc:1403] T 8ce587f6acf5408d93fc1e2e2021b144 P d2afc49f513f429cbd2f8792faeba212: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:44.605202 32135 raft_consensus.cc:359] T 8ce587f6acf5408d93fc1e2e2021b144 P d2afc49f513f429cbd2f8792faeba212 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d2afc49f513f429cbd2f8792faeba212" member_type: VOTER last_known_addr { host: "127.30.211.129" port: 43793 } }
I20260812 06:18:44.605297 32135 raft_consensus.cc:385] T 8ce587f6acf5408d93fc1e2e2021b144 P d2afc49f513f429cbd2f8792faeba212 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:44.605319 32135 raft_consensus.cc:740] T 8ce587f6acf5408d93fc1e2e2021b144 P d2afc49f513f429cbd2f8792faeba212 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: d2afc49f513f429cbd2f8792faeba212, State: Initialized, Role: FOLLOWER
I20260812 06:18:44.605520 32135 consensus_queue.cc:260] T 8ce587f6acf5408d93fc1e2e2021b144 P d2afc49f513f429cbd2f8792faeba212 [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: "d2afc49f513f429cbd2f8792faeba212" member_type: VOTER last_known_addr { host: "127.30.211.129" port: 43793 } }
I20260812 06:18:44.605607 32135 raft_consensus.cc:399] T 8ce587f6acf5408d93fc1e2e2021b144 P d2afc49f513f429cbd2f8792faeba212 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:44.605656 32135 raft_consensus.cc:493] T 8ce587f6acf5408d93fc1e2e2021b144 P d2afc49f513f429cbd2f8792faeba212 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:44.605713 32135 raft_consensus.cc:3060] T 8ce587f6acf5408d93fc1e2e2021b144 P d2afc49f513f429cbd2f8792faeba212 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:44.606475 32135 raft_consensus.cc:515] T 8ce587f6acf5408d93fc1e2e2021b144 P d2afc49f513f429cbd2f8792faeba212 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d2afc49f513f429cbd2f8792faeba212" member_type: VOTER last_known_addr { host: "127.30.211.129" port: 43793 } }
I20260812 06:18:44.606652 32135 leader_election.cc:304] T 8ce587f6acf5408d93fc1e2e2021b144 P d2afc49f513f429cbd2f8792faeba212 [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: d2afc49f513f429cbd2f8792faeba212; no voters: 
I20260812 06:18:44.606889 32135 leader_election.cc:290] T 8ce587f6acf5408d93fc1e2e2021b144 P d2afc49f513f429cbd2f8792faeba212 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:44.607048 32139 raft_consensus.cc:2804] T 8ce587f6acf5408d93fc1e2e2021b144 P d2afc49f513f429cbd2f8792faeba212 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:44.607232 32135 ts_tablet_manager.cc:1434] T 8ce587f6acf5408d93fc1e2e2021b144 P d2afc49f513f429cbd2f8792faeba212: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:44.607280 32122 heartbeater.cc:499] Master 127.30.211.190:43787 was elected leader, sending a full tablet report...
I20260812 06:18:44.607317 32139 raft_consensus.cc:697] T 8ce587f6acf5408d93fc1e2e2021b144 P d2afc49f513f429cbd2f8792faeba212 [term 1 LEADER]: Becoming Leader. State: Replica: d2afc49f513f429cbd2f8792faeba212, State: Running, Role: LEADER
I20260812 06:18:44.607524 32139 consensus_queue.cc:237] T 8ce587f6acf5408d93fc1e2e2021b144 P d2afc49f513f429cbd2f8792faeba212 [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: "d2afc49f513f429cbd2f8792faeba212" member_type: VOTER last_known_addr { host: "127.30.211.129" port: 43793 } }
I20260812 06:18:44.609045 31916 catalog_manager.cc:5719] T 8ce587f6acf5408d93fc1e2e2021b144 P d2afc49f513f429cbd2f8792faeba212 reported cstate change: term changed from 0 to 1, leader changed from <none> to d2afc49f513f429cbd2f8792faeba212 (127.30.211.129). New cstate: current_term: 1 leader_uuid: "d2afc49f513f429cbd2f8792faeba212" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d2afc49f513f429cbd2f8792faeba212" member_type: VOTER last_known_addr { host: "127.30.211.129" port: 43793 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:44.670114 31566 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.055s	user 0.020s	sys 0.004s
I20260812 06:18:44.819621 32123 maintenance_manager.cc:419] P d2afc49f513f429cbd2f8792faeba212: Scheduling FlushMRSOp(8ce587f6acf5408d93fc1e2e2021b144): perf score=19.054940
I20260812 06:18:44.979758 32030 maintenance_manager.cc:643] P d2afc49f513f429cbd2f8792faeba212: FlushMRSOp(8ce587f6acf5408d93fc1e2e2021b144) complete. Timing: real 0.160s	user 0.133s	sys 0.020s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":94,"dirs.run_cpu_time_us":231,"dirs.run_wall_time_us":992,"drs_written":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4,"lbm_write_time_us":41985,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:18:44.980494 32123 maintenance_manager.cc:419] P d2afc49f513f429cbd2f8792faeba212: Scheduling LogGCOp(8ce587f6acf5408d93fc1e2e2021b144): free 20743880 bytes of WAL
I20260812 06:18:44.980809 32030 log_reader.cc:385] T 8ce587f6acf5408d93fc1e2e2021b144: removed 2 log segments from log reader
I20260812 06:18:44.980861 32030 log.cc:1079] T 8ce587f6acf5408d93fc1e2e2021b144 P d2afc49f513f429cbd2f8792faeba212: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/8ce587f6acf5408d93fc1e2e2021b144/wal-000000001 (ops 1-6)
I20260812 06:18:44.980892 32030 log.cc:1079] T 8ce587f6acf5408d93fc1e2e2021b144 P d2afc49f513f429cbd2f8792faeba212: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/8ce587f6acf5408d93fc1e2e2021b144/wal-000000002 (ops 7-11)
I20260812 06:18:44.985509 32030 maintenance_manager.cc:643] P d2afc49f513f429cbd2f8792faeba212: LogGCOp(8ce587f6acf5408d93fc1e2e2021b144) complete. Timing: real 0.005s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:18:44.985946 32123 maintenance_manager.cc:419] P d2afc49f513f429cbd2f8792faeba212: Scheduling FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144): perf score=2.188937
I20260812 06:18:45.002260 32030 maintenance_manager.cc:643] P d2afc49f513f429cbd2f8792faeba212: FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144) complete. Timing: real 0.016s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6173,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.002830 32123 maintenance_manager.cc:419] P d2afc49f513f429cbd2f8792faeba212: Scheduling UndoDeltaBlockGCOp(8ce587f6acf5408d93fc1e2e2021b144): 16411392 bytes on disk
I20260812 06:18:45.003391 32030 maintenance_manager.cc:643] P d2afc49f513f429cbd2f8792faeba212: UndoDeltaBlockGCOp(8ce587f6acf5408d93fc1e2e2021b144) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":106,"lbm_reads_lt_1ms":4}
I20260812 06:18:45.003865 32123 maintenance_manager.cc:419] P d2afc49f513f429cbd2f8792faeba212: Scheduling MajorDeltaCompactionOp(8ce587f6acf5408d93fc1e2e2021b144): perf score=1.000000
I20260812 06:18:45.169953 32030 maintenance_manager.cc:643] P d2afc49f513f429cbd2f8792faeba212: MajorDeltaCompactionOp(8ce587f6acf5408d93fc1e2e2021b144) complete. Timing: real 0.166s	user 0.100s	sys 0.055s 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":743,"lbm_read_time_us":10371,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24967,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":363,"threads_started":5,"update_count":2000}
I20260812 06:18:45.170782 32123 maintenance_manager.cc:419] P d2afc49f513f429cbd2f8792faeba212: Scheduling FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144): perf score=14.095187
I20260812 06:18:45.224275 32030 maintenance_manager.cc:643] P d2afc49f513f429cbd2f8792faeba212: FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144) complete. Timing: real 0.053s	user 0.023s	sys 0.029s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23034,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:45.224803 32123 maintenance_manager.cc:419] P d2afc49f513f429cbd2f8792faeba212: Scheduling MajorDeltaCompactionOp(8ce587f6acf5408d93fc1e2e2021b144): perf score=1.000000
I20260812 06:18:45.380239 32030 maintenance_manager.cc:643] P d2afc49f513f429cbd2f8792faeba212: MajorDeltaCompactionOp(8ce587f6acf5408d93fc1e2e2021b144) complete. Timing: real 0.155s	user 0.104s	sys 0.050s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672158,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":2051,"lbm_read_time_us":10860,"lbm_reads_lt_1ms":463,"lbm_write_time_us":26217,"lbm_writes_lt_1ms":443,"mutex_wait_us":1414,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2000}
I20260812 06:18:45.380899 32123 maintenance_manager.cc:419] P d2afc49f513f429cbd2f8792faeba212: Scheduling FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144): perf score=14.095187
I20260812 06:18:45.430377 32030 maintenance_manager.cc:643] P d2afc49f513f429cbd2f8792faeba212: FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144) complete. Timing: real 0.049s	user 0.030s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23754,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:18:45.430946 32123 maintenance_manager.cc:419] P d2afc49f513f429cbd2f8792faeba212: Scheduling FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144): perf score=2.188937
I20260812 06:18:45.444388 32030 maintenance_manager.cc:643] P d2afc49f513f429cbd2f8792faeba212: FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144) complete. Timing: real 0.013s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4785,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.444937 32123 maintenance_manager.cc:419] P d2afc49f513f429cbd2f8792faeba212: Scheduling MajorDeltaCompactionOp(8ce587f6acf5408d93fc1e2e2021b144): perf score=1.000000
I20260812 06:18:45.636428 32030 maintenance_manager.cc:643] P d2afc49f513f429cbd2f8792faeba212: MajorDeltaCompactionOp(8ce587f6acf5408d93fc1e2e2021b144) complete. Timing: real 0.191s	user 0.100s	sys 0.082s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":330,"lbm_read_time_us":13520,"lbm_reads_lt_1ms":564,"lbm_write_time_us":29298,"lbm_writes_lt_1ms":543,"mutex_wait_us":19,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":24448,"update_count":2500}
I20260812 06:18:45.637156 32123 maintenance_manager.cc:419] P d2afc49f513f429cbd2f8792faeba212: Scheduling FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144): perf score=14.095187
I20260812 06:18:45.696413 32030 maintenance_manager.cc:643] P d2afc49f513f429cbd2f8792faeba212: FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144) complete. Timing: real 0.059s	user 0.047s	sys 0.011s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":26542,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:45.696926 32123 maintenance_manager.cc:419] P d2afc49f513f429cbd2f8792faeba212: Scheduling FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144): perf score=2.188937
I20260812 06:18:45.708523 32030 maintenance_manager.cc:643] P d2afc49f513f429cbd2f8792faeba212: FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144) complete. Timing: real 0.011s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4157,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.709321 32123 maintenance_manager.cc:419] P d2afc49f513f429cbd2f8792faeba212: Scheduling MajorDeltaCompactionOp(8ce587f6acf5408d93fc1e2e2021b144): perf score=1.000000
I20260812 06:18:45.857447 32030 maintenance_manager.cc:643] P d2afc49f513f429cbd2f8792faeba212: MajorDeltaCompactionOp(8ce587f6acf5408d93fc1e2e2021b144) complete. Timing: real 0.148s	user 0.120s	sys 0.028s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":363,"lbm_read_time_us":11391,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30170,"lbm_writes_lt_1ms":543,"mutex_wait_us":68,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12544,"update_count":2500}
I20260812 06:18:45.858103 32123 maintenance_manager.cc:419] P d2afc49f513f429cbd2f8792faeba212: Scheduling FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144): perf score=10.126437
I20260812 06:18:45.900559 32030 maintenance_manager.cc:643] P d2afc49f513f429cbd2f8792faeba212: FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144) complete. Timing: real 0.042s	user 0.034s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18566,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:45.901109 32123 maintenance_manager.cc:419] P d2afc49f513f429cbd2f8792faeba212: Scheduling FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144): perf score=2.188937
I20260812 06:18:45.911967 32030 maintenance_manager.cc:643] P d2afc49f513f429cbd2f8792faeba212: FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4216,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.912549 32123 maintenance_manager.cc:419] P d2afc49f513f429cbd2f8792faeba212: Scheduling MajorDeltaCompactionOp(8ce587f6acf5408d93fc1e2e2021b144): perf score=1.000000
I20260812 06:18:46.048727 32030 maintenance_manager.cc:643] P d2afc49f513f429cbd2f8792faeba212: MajorDeltaCompactionOp(8ce587f6acf5408d93fc1e2e2021b144) complete. Timing: real 0.136s	user 0.112s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":562,"lbm_read_time_us":9918,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26316,"lbm_writes_lt_1ms":443,"mutex_wait_us":300,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9856,"update_count":2000}
I20260812 06:18:46.052394 32123 maintenance_manager.cc:419] P d2afc49f513f429cbd2f8792faeba212: Scheduling FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144): perf score=10.126437
I20260812 06:18:46.092641 32030 maintenance_manager.cc:643] P d2afc49f513f429cbd2f8792faeba212: FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144) complete. Timing: real 0.040s	user 0.029s	sys 0.005s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":15006,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:46.093197 32123 maintenance_manager.cc:419] P d2afc49f513f429cbd2f8792faeba212: Scheduling FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144): perf score=2.188937
I20260812 06:18:46.104532 32030 maintenance_manager.cc:643] P d2afc49f513f429cbd2f8792faeba212: FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144) complete. Timing: real 0.011s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4252,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:46.105252 32123 maintenance_manager.cc:419] P d2afc49f513f429cbd2f8792faeba212: Scheduling MajorDeltaCompactionOp(8ce587f6acf5408d93fc1e2e2021b144): perf score=1.000000
I20260812 06:18:46.236529 32030 maintenance_manager.cc:643] P d2afc49f513f429cbd2f8792faeba212: MajorDeltaCompactionOp(8ce587f6acf5408d93fc1e2e2021b144) complete. Timing: real 0.131s	user 0.110s	sys 0.020s 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":710,"lbm_read_time_us":10695,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23796,"lbm_writes_lt_1ms":443,"mutex_wait_us":322,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10752,"update_count":2000}
I20260812 06:18:46.237138 32123 maintenance_manager.cc:419] P d2afc49f513f429cbd2f8792faeba212: Scheduling FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144): perf score=10.126437
I20260812 06:18:46.290679 32030 maintenance_manager.cc:643] P d2afc49f513f429cbd2f8792faeba212: FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144) complete. Timing: real 0.053s	user 0.030s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16675,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:46.291342 32123 maintenance_manager.cc:419] P d2afc49f513f429cbd2f8792faeba212: Scheduling FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144): perf score=2.188937
I20260812 06:18:46.302539 32030 maintenance_manager.cc:643] P d2afc49f513f429cbd2f8792faeba212: FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4212,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:46.303066 32123 maintenance_manager.cc:419] P d2afc49f513f429cbd2f8792faeba212: Scheduling FlushMRSOp(8ce587f6acf5408d93fc1e2e2021b144): perf score=1.000000
I20260812 06:18:46.345975 32030 maintenance_manager.cc:643] P d2afc49f513f429cbd2f8792faeba212: FlushMRSOp(8ce587f6acf5408d93fc1e2e2021b144) complete. Timing: real 0.043s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":74,"dirs.run_cpu_time_us":219,"dirs.run_wall_time_us":1668,"drs_written":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1558,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:46.346698 32123 maintenance_manager.cc:419] P d2afc49f513f429cbd2f8792faeba212: Scheduling LogGCOp(8ce587f6acf5408d93fc1e2e2021b144): free 121006430 bytes of WAL
I20260812 06:18:46.346952 32030 log_reader.cc:385] T 8ce587f6acf5408d93fc1e2e2021b144: removed 12 log segments from log reader
I20260812 06:18:46.346999 32030 log.cc:1079] T 8ce587f6acf5408d93fc1e2e2021b144 P d2afc49f513f429cbd2f8792faeba212: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/8ce587f6acf5408d93fc1e2e2021b144/wal-000000003 (ops 12-16)
I20260812 06:18:46.347029 32030 log.cc:1079] T 8ce587f6acf5408d93fc1e2e2021b144 P d2afc49f513f429cbd2f8792faeba212: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/8ce587f6acf5408d93fc1e2e2021b144/wal-000000004 (ops 17-21)
I20260812 06:18:46.347081 32030 log.cc:1079] T 8ce587f6acf5408d93fc1e2e2021b144 P d2afc49f513f429cbd2f8792faeba212: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/8ce587f6acf5408d93fc1e2e2021b144/wal-000000005 (ops 22-26)
I20260812 06:18:46.347132 32030 log.cc:1079] T 8ce587f6acf5408d93fc1e2e2021b144 P d2afc49f513f429cbd2f8792faeba212: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/8ce587f6acf5408d93fc1e2e2021b144/wal-000000006 (ops 27-31)
I20260812 06:18:46.347183 32030 log.cc:1079] T 8ce587f6acf5408d93fc1e2e2021b144 P d2afc49f513f429cbd2f8792faeba212: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/8ce587f6acf5408d93fc1e2e2021b144/wal-000000007 (ops 32-36)
I20260812 06:18:46.347226 32030 log.cc:1079] T 8ce587f6acf5408d93fc1e2e2021b144 P d2afc49f513f429cbd2f8792faeba212: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/8ce587f6acf5408d93fc1e2e2021b144/wal-000000008 (ops 37-40)
I20260812 06:18:46.347276 32030 log.cc:1079] T 8ce587f6acf5408d93fc1e2e2021b144 P d2afc49f513f429cbd2f8792faeba212: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/8ce587f6acf5408d93fc1e2e2021b144/wal-000000009 (ops 41-45)
I20260812 06:18:46.347319 32030 log.cc:1079] T 8ce587f6acf5408d93fc1e2e2021b144 P d2afc49f513f429cbd2f8792faeba212: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/8ce587f6acf5408d93fc1e2e2021b144/wal-000000010 (ops 46-50)
I20260812 06:18:46.347352 32030 log.cc:1079] T 8ce587f6acf5408d93fc1e2e2021b144 P d2afc49f513f429cbd2f8792faeba212: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/8ce587f6acf5408d93fc1e2e2021b144/wal-000000011 (ops 51-55)
I20260812 06:18:46.347396 32030 log.cc:1079] T 8ce587f6acf5408d93fc1e2e2021b144 P d2afc49f513f429cbd2f8792faeba212: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/8ce587f6acf5408d93fc1e2e2021b144/wal-000000012 (ops 56-60)
I20260812 06:18:46.347426 32030 log.cc:1079] T 8ce587f6acf5408d93fc1e2e2021b144 P d2afc49f513f429cbd2f8792faeba212: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/8ce587f6acf5408d93fc1e2e2021b144/wal-000000013 (ops 61-65)
I20260812 06:18:46.347461 32030 log.cc:1079] T 8ce587f6acf5408d93fc1e2e2021b144 P d2afc49f513f429cbd2f8792faeba212: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/8ce587f6acf5408d93fc1e2e2021b144/wal-000000014 (ops 66-70)
I20260812 06:18:46.373582 32030 maintenance_manager.cc:643] P d2afc49f513f429cbd2f8792faeba212: LogGCOp(8ce587f6acf5408d93fc1e2e2021b144) complete. Timing: real 0.027s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:18:46.374037 32123 maintenance_manager.cc:419] P d2afc49f513f429cbd2f8792faeba212: Scheduling UndoDeltaBlockGCOp(8ce587f6acf5408d93fc1e2e2021b144): 473 bytes on disk
I20260812 06:18:46.374672 32030 maintenance_manager.cc:643] P d2afc49f513f429cbd2f8792faeba212: UndoDeltaBlockGCOp(8ce587f6acf5408d93fc1e2e2021b144) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":65,"lbm_reads_lt_1ms":4}
I20260812 06:18:46.375164 32123 maintenance_manager.cc:419] P d2afc49f513f429cbd2f8792faeba212: Scheduling FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144): perf score=2.188937
I20260812 06:18:46.391486 32030 maintenance_manager.cc:643] P d2afc49f513f429cbd2f8792faeba212: FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144) complete. Timing: real 0.016s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4695,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:46.392062 32123 maintenance_manager.cc:419] P d2afc49f513f429cbd2f8792faeba212: Scheduling FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144): perf score=2.188937
I20260812 06:18:46.403177 32030 maintenance_manager.cc:643] P d2afc49f513f429cbd2f8792faeba212: FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4050,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:46.403807 32123 maintenance_manager.cc:419] P d2afc49f513f429cbd2f8792faeba212: Scheduling MajorDeltaCompactionOp(8ce587f6acf5408d93fc1e2e2021b144): perf score=1.000000
I20260812 06:18:46.631196 32030 maintenance_manager.cc:643] P d2afc49f513f429cbd2f8792faeba212: MajorDeltaCompactionOp(8ce587f6acf5408d93fc1e2e2021b144) complete. Timing: real 0.227s	user 0.128s	sys 0.085s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877338,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1150,"lbm_read_time_us":15141,"lbm_reads_lt_1ms":674,"lbm_write_time_us":34361,"lbm_writes_lt_1ms":643,"mutex_wait_us":72,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":4480,"thread_start_us":89,"threads_started":1,"update_count":3000}
I20260812 06:18:46.631910 32123 maintenance_manager.cc:419] P d2afc49f513f429cbd2f8792faeba212: Scheduling FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144): perf score=18.063937
I20260812 06:18:46.699384 32030 maintenance_manager.cc:643] P d2afc49f513f429cbd2f8792faeba212: FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144) complete. Timing: real 0.067s	user 0.035s	sys 0.021s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":27100,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:46.699898 32123 maintenance_manager.cc:419] P d2afc49f513f429cbd2f8792faeba212: Scheduling FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144): perf score=2.188937
I20260812 06:18:46.711038 32030 maintenance_manager.cc:643] P d2afc49f513f429cbd2f8792faeba212: FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144) complete. Timing: real 0.011s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3918,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:46.711578 32123 maintenance_manager.cc:419] P d2afc49f513f429cbd2f8792faeba212: Scheduling MajorDeltaCompactionOp(8ce587f6acf5408d93fc1e2e2021b144): perf score=1.000000
I20260812 06:18:46.928301 32030 maintenance_manager.cc:643] P d2afc49f513f429cbd2f8792faeba212: MajorDeltaCompactionOp(8ce587f6acf5408d93fc1e2e2021b144) complete. Timing: real 0.216s	user 0.125s	sys 0.091s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877103,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":491,"lbm_read_time_us":15828,"lbm_reads_lt_1ms":672,"lbm_write_time_us":35242,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":54912,"update_count":3000}
I20260812 06:18:46.929960 32123 maintenance_manager.cc:419] P d2afc49f513f429cbd2f8792faeba212: Scheduling FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144): perf score=15.087375
I20260812 06:18:46.974098 32030 maintenance_manager.cc:643] P d2afc49f513f429cbd2f8792faeba212: FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144) complete. Timing: real 0.044s	user 0.026s	sys 0.015s Metrics: {"bytes_written":16573998,"delete_count":0,"lbm_write_time_us":18669,"lbm_writes_lt_1ms":407,"reinsert_count":0,"update_count":2020}
I20260812 06:18:46.974689 32123 maintenance_manager.cc:419] P d2afc49f513f429cbd2f8792faeba212: Scheduling FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144): perf score=2.188937
I20260812 06:18:47.002779 32030 maintenance_manager.cc:643] P d2afc49f513f429cbd2f8792faeba212: FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144) complete. Timing: real 0.028s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3938559,"delete_count":0,"lbm_write_time_us":5633,"lbm_writes_lt_1ms":99,"reinsert_count":0,"update_count":480}
I20260812 06:18:47.003221 32123 maintenance_manager.cc:419] P d2afc49f513f429cbd2f8792faeba212: Scheduling FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144): perf score=2.188937
I20260812 06:18:47.013983 32030 maintenance_manager.cc:643] P d2afc49f513f429cbd2f8792faeba212: FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4097,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:47.014439 32123 maintenance_manager.cc:419] P d2afc49f513f429cbd2f8792faeba212: Scheduling MajorDeltaCompactionOp(8ce587f6acf5408d93fc1e2e2021b144): perf score=1.000000
I20260812 06:18:47.233703 32030 maintenance_manager.cc:643] P d2afc49f513f429cbd2f8792faeba212: MajorDeltaCompactionOp(8ce587f6acf5408d93fc1e2e2021b144) complete. Timing: real 0.219s	user 0.143s	sys 0.075s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877216,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":779,"lbm_read_time_us":15213,"lbm_reads_lt_1ms":673,"lbm_write_time_us":34495,"lbm_writes_lt_1ms":643,"mutex_wait_us":374,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":3000}
I20260812 06:18:47.234579 32123 maintenance_manager.cc:419] P d2afc49f513f429cbd2f8792faeba212: Scheduling FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144): perf score=14.095187
I20260812 06:18:47.283475 32030 maintenance_manager.cc:643] P d2afc49f513f429cbd2f8792faeba212: FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144) complete. Timing: real 0.049s	user 0.029s	sys 0.016s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21525,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:47.283970 32123 maintenance_manager.cc:419] P d2afc49f513f429cbd2f8792faeba212: Scheduling FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144): perf score=2.188937
I20260812 06:18:47.301726 32030 maintenance_manager.cc:643] P d2afc49f513f429cbd2f8792faeba212: FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144) complete. Timing: real 0.018s	user 0.011s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6705,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:47.302451 32123 maintenance_manager.cc:419] P d2afc49f513f429cbd2f8792faeba212: Scheduling MajorDeltaCompactionOp(8ce587f6acf5408d93fc1e2e2021b144): perf score=1.000000
I20260812 06:18:47.503669 32030 maintenance_manager.cc:643] P d2afc49f513f429cbd2f8792faeba212: MajorDeltaCompactionOp(8ce587f6acf5408d93fc1e2e2021b144) complete. Timing: real 0.201s	user 0.139s	sys 0.057s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":166,"lbm_read_time_us":15234,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33414,"lbm_writes_lt_1ms":543,"mutex_wait_us":62,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8064,"update_count":2500}
I20260812 06:18:47.504459 32123 maintenance_manager.cc:419] P d2afc49f513f429cbd2f8792faeba212: Scheduling FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144): perf score=14.095187
I20260812 06:18:47.566251 32030 maintenance_manager.cc:643] P d2afc49f513f429cbd2f8792faeba212: FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144) complete. Timing: real 0.062s	user 0.034s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25308,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"mutex_wait_us":1,"reinsert_count":0,"update_count":2000}
I20260812 06:18:47.566874 32123 maintenance_manager.cc:419] P d2afc49f513f429cbd2f8792faeba212: Scheduling FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144): perf score=2.188937
I20260812 06:18:47.579339 32030 maintenance_manager.cc:643] P d2afc49f513f429cbd2f8792faeba212: FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144) complete. Timing: real 0.012s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4373,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:47.579867 32123 maintenance_manager.cc:419] P d2afc49f513f429cbd2f8792faeba212: Scheduling MajorDeltaCompactionOp(8ce587f6acf5408d93fc1e2e2021b144): perf score=1.000000
I20260812 06:18:47.757962 32030 maintenance_manager.cc:643] P d2afc49f513f429cbd2f8792faeba212: MajorDeltaCompactionOp(8ce587f6acf5408d93fc1e2e2021b144) complete. Timing: real 0.178s	user 0.119s	sys 0.058s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1847,"lbm_read_time_us":14616,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27845,"lbm_writes_lt_1ms":543,"mutex_wait_us":415,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":19584,"update_count":2500}
I20260812 06:18:47.758932 32123 maintenance_manager.cc:419] P d2afc49f513f429cbd2f8792faeba212: Scheduling FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144): perf score=14.095187
I20260812 06:18:47.822577 32030 maintenance_manager.cc:643] P d2afc49f513f429cbd2f8792faeba212: FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144) complete. Timing: real 0.063s	user 0.033s	sys 0.028s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23090,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:47.823498 32123 maintenance_manager.cc:419] P d2afc49f513f429cbd2f8792faeba212: Scheduling FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144): perf score=2.188937
I20260812 06:18:47.845903 32030 maintenance_manager.cc:643] P d2afc49f513f429cbd2f8792faeba212: FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144) complete. Timing: real 0.022s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6615,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:47.846454 32123 maintenance_manager.cc:419] P d2afc49f513f429cbd2f8792faeba212: Scheduling FlushMRSOp(8ce587f6acf5408d93fc1e2e2021b144): perf score=1.000000
I20260812 06:18:47.890636 32030 maintenance_manager.cc:643] P d2afc49f513f429cbd2f8792faeba212: FlushMRSOp(8ce587f6acf5408d93fc1e2e2021b144) complete. Timing: real 0.044s	user 0.026s	sys 0.001s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":63,"dirs.run_cpu_time_us":225,"dirs.run_wall_time_us":1506,"drs_written":1,"lbm_read_time_us":91,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2292,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:47.891566 32123 maintenance_manager.cc:419] P d2afc49f513f429cbd2f8792faeba212: Scheduling UndoDeltaBlockGCOp(8ce587f6acf5408d93fc1e2e2021b144): 472 bytes on disk
I20260812 06:18:47.892256 32030 maintenance_manager.cc:643] P d2afc49f513f429cbd2f8792faeba212: UndoDeltaBlockGCOp(8ce587f6acf5408d93fc1e2e2021b144) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":65,"lbm_reads_lt_1ms":4}
I20260812 06:18:47.892972 32123 maintenance_manager.cc:419] P d2afc49f513f429cbd2f8792faeba212: Scheduling FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144): perf score=3.181125
I20260812 06:18:47.914029 32030 maintenance_manager.cc:643] P d2afc49f513f429cbd2f8792faeba212: FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144) complete. Timing: real 0.021s	user 0.014s	sys 0.003s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":7410,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:47.914559 32123 maintenance_manager.cc:419] P d2afc49f513f429cbd2f8792faeba212: Scheduling LogGCOp(8ce587f6acf5408d93fc1e2e2021b144): free 120553390 bytes of WAL
I20260812 06:18:47.914806 32030 log_reader.cc:385] T 8ce587f6acf5408d93fc1e2e2021b144: removed 12 log segments from log reader
I20260812 06:18:47.914852 32030 log.cc:1079] T 8ce587f6acf5408d93fc1e2e2021b144 P d2afc49f513f429cbd2f8792faeba212: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/8ce587f6acf5408d93fc1e2e2021b144/wal-000000015 (ops 71-74)
I20260812 06:18:47.914881 32030 log.cc:1079] T 8ce587f6acf5408d93fc1e2e2021b144 P d2afc49f513f429cbd2f8792faeba212: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/8ce587f6acf5408d93fc1e2e2021b144/wal-000000016 (ops 75-79)
I20260812 06:18:47.914932 32030 log.cc:1079] T 8ce587f6acf5408d93fc1e2e2021b144 P d2afc49f513f429cbd2f8792faeba212: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/8ce587f6acf5408d93fc1e2e2021b144/wal-000000017 (ops 80-84)
I20260812 06:18:47.914976 32030 log.cc:1079] T 8ce587f6acf5408d93fc1e2e2021b144 P d2afc49f513f429cbd2f8792faeba212: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/8ce587f6acf5408d93fc1e2e2021b144/wal-000000018 (ops 85-88)
I20260812 06:18:47.915002 32030 log.cc:1079] T 8ce587f6acf5408d93fc1e2e2021b144 P d2afc49f513f429cbd2f8792faeba212: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/8ce587f6acf5408d93fc1e2e2021b144/wal-000000019 (ops 89-93)
I20260812 06:18:47.915079 32030 log.cc:1079] T 8ce587f6acf5408d93fc1e2e2021b144 P d2afc49f513f429cbd2f8792faeba212: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/8ce587f6acf5408d93fc1e2e2021b144/wal-000000020 (ops 94-98)
I20260812 06:18:47.915107 32030 log.cc:1079] T 8ce587f6acf5408d93fc1e2e2021b144 P d2afc49f513f429cbd2f8792faeba212: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/8ce587f6acf5408d93fc1e2e2021b144/wal-000000021 (ops 99-103)
I20260812 06:18:47.915146 32030 log.cc:1079] T 8ce587f6acf5408d93fc1e2e2021b144 P d2afc49f513f429cbd2f8792faeba212: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/8ce587f6acf5408d93fc1e2e2021b144/wal-000000022 (ops 104-108)
I20260812 06:18:47.915185 32030 log.cc:1079] T 8ce587f6acf5408d93fc1e2e2021b144 P d2afc49f513f429cbd2f8792faeba212: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/8ce587f6acf5408d93fc1e2e2021b144/wal-000000023 (ops 109-113)
I20260812 06:18:47.915225 32030 log.cc:1079] T 8ce587f6acf5408d93fc1e2e2021b144 P d2afc49f513f429cbd2f8792faeba212: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/8ce587f6acf5408d93fc1e2e2021b144/wal-000000024 (ops 114-118)
I20260812 06:18:47.915264 32030 log.cc:1079] T 8ce587f6acf5408d93fc1e2e2021b144 P d2afc49f513f429cbd2f8792faeba212: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/8ce587f6acf5408d93fc1e2e2021b144/wal-000000025 (ops 119-123)
I20260812 06:18:47.915304 32030 log.cc:1079] T 8ce587f6acf5408d93fc1e2e2021b144 P d2afc49f513f429cbd2f8792faeba212: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/8ce587f6acf5408d93fc1e2e2021b144/wal-000000026 (ops 124-128)
I20260812 06:18:47.942921 32030 maintenance_manager.cc:643] P d2afc49f513f429cbd2f8792faeba212: LogGCOp(8ce587f6acf5408d93fc1e2e2021b144) complete. Timing: real 0.028s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:18:47.943392 32123 maintenance_manager.cc:419] P d2afc49f513f429cbd2f8792faeba212: Scheduling FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144): perf score=2.188937
I20260812 06:18:47.968271 32030 maintenance_manager.cc:643] P d2afc49f513f429cbd2f8792faeba212: FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144) complete. Timing: real 0.025s	user 0.010s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5576,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:47.968771 32123 maintenance_manager.cc:419] P d2afc49f513f429cbd2f8792faeba212: Scheduling LogGCOp(8ce587f6acf5408d93fc1e2e2021b144): free 11564891 bytes of WAL
I20260812 06:18:47.969002 32030 log_reader.cc:385] T 8ce587f6acf5408d93fc1e2e2021b144: removed 1 log segments from log reader
I20260812 06:18:47.969048 32030 log.cc:1079] T 8ce587f6acf5408d93fc1e2e2021b144 P d2afc49f513f429cbd2f8792faeba212: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/8ce587f6acf5408d93fc1e2e2021b144/wal-000000027 (ops 129-132)
I20260812 06:18:47.971397 32030 maintenance_manager.cc:643] P d2afc49f513f429cbd2f8792faeba212: LogGCOp(8ce587f6acf5408d93fc1e2e2021b144) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:18:47.971729 32123 maintenance_manager.cc:419] P d2afc49f513f429cbd2f8792faeba212: Scheduling FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144): perf score=2.188937
I20260812 06:18:47.983311 32030 maintenance_manager.cc:643] P d2afc49f513f429cbd2f8792faeba212: FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4071,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:47.983924 32123 maintenance_manager.cc:419] P d2afc49f513f429cbd2f8792faeba212: Scheduling MajorDeltaCompactionOp(8ce587f6acf5408d93fc1e2e2021b144): perf score=1.000000
I20260812 06:18:48.228258 32030 maintenance_manager.cc:643] P d2afc49f513f429cbd2f8792faeba212: MajorDeltaCompactionOp(8ce587f6acf5408d93fc1e2e2021b144) complete. Timing: real 0.244s	user 0.167s	sys 0.077s Metrics: {"cfile_cache_miss":835,"cfile_cache_miss_bytes":37082270,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":510,"lbm_read_time_us":17138,"lbm_reads_lt_1ms":875,"lbm_write_time_us":45229,"lbm_writes_lt_1ms":843,"mutex_wait_us":67,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":13952,"thread_start_us":80,"threads_started":1,"update_count":4000}
I20260812 06:18:48.229048 32123 maintenance_manager.cc:419] P d2afc49f513f429cbd2f8792faeba212: Scheduling FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144): perf score=19.056125
I20260812 06:18:48.307729 32030 maintenance_manager.cc:643] P d2afc49f513f429cbd2f8792faeba212: FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144) complete. Timing: real 0.078s	user 0.035s	sys 0.025s Metrics: {"bytes_written":20799484,"delete_count":0,"lbm_write_time_us":28352,"lbm_writes_lt_1ms":510,"reinsert_count":0,"update_count":2535}
I20260812 06:18:48.308327 32123 maintenance_manager.cc:419] P d2afc49f513f429cbd2f8792faeba212: Scheduling FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144): perf score=6.157687
I20260812 06:18:48.334816 32030 maintenance_manager.cc:643] P d2afc49f513f429cbd2f8792faeba212: FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144) complete. Timing: real 0.026s	user 0.010s	sys 0.013s Metrics: {"bytes_written":7917914,"delete_count":0,"lbm_write_time_us":10995,"lbm_writes_lt_1ms":196,"reinsert_count":0,"update_count":965}
I20260812 06:18:48.335289 32123 maintenance_manager.cc:419] P d2afc49f513f429cbd2f8792faeba212: Scheduling MajorDeltaCompactionOp(8ce587f6acf5408d93fc1e2e2021b144): perf score=1.000000
I20260812 06:18:48.532217 32030 maintenance_manager.cc:643] P d2afc49f513f429cbd2f8792faeba212: MajorDeltaCompactionOp(8ce587f6acf5408d93fc1e2e2021b144) complete. Timing: real 0.197s	user 0.151s	sys 0.044s Metrics: {"cfile_cache_miss":732,"cfile_cache_miss_bytes":32979520,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1397,"lbm_read_time_us":13348,"lbm_reads_lt_1ms":764,"lbm_write_time_us":43030,"lbm_writes_lt_1ms":743,"mutex_wait_us":27,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":18048,"update_count":3500}
I20260812 06:18:48.533020 32123 maintenance_manager.cc:419] P d2afc49f513f429cbd2f8792faeba212: Scheduling FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144): perf score=15.087375
I20260812 06:18:48.594200 32030 maintenance_manager.cc:643] P d2afc49f513f429cbd2f8792faeba212: FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144) complete. Timing: real 0.061s	user 0.041s	sys 0.017s Metrics: {"bytes_written":16820141,"delete_count":0,"lbm_write_time_us":25892,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":411,"reinsert_count":0,"update_count":2050}
I20260812 06:18:48.594794 32123 maintenance_manager.cc:419] P d2afc49f513f429cbd2f8792faeba212: Scheduling FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144): perf score=2.188937
I20260812 06:18:48.615024 32030 maintenance_manager.cc:643] P d2afc49f513f429cbd2f8792faeba212: FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144) complete. Timing: real 0.020s	user 0.001s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4339,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:48.615540 32123 maintenance_manager.cc:419] P d2afc49f513f429cbd2f8792faeba212: Scheduling FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144): perf score=2.188937
I20260812 06:18:48.626965 32030 maintenance_manager.cc:643] P d2afc49f513f429cbd2f8792faeba212: FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4402,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:48.627482 32123 maintenance_manager.cc:419] P d2afc49f513f429cbd2f8792faeba212: Scheduling MajorDeltaCompactionOp(8ce587f6acf5408d93fc1e2e2021b144): perf score=1.000000
I20260812 06:18:48.823505 32030 maintenance_manager.cc:643] P d2afc49f513f429cbd2f8792faeba212: MajorDeltaCompactionOp(8ce587f6acf5408d93fc1e2e2021b144) complete. Timing: real 0.196s	user 0.147s	sys 0.048s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877205,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":541,"lbm_read_time_us":13406,"lbm_reads_lt_1ms":673,"lbm_write_time_us":41093,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":5632,"update_count":3000}
I20260812 06:18:48.824182 32123 maintenance_manager.cc:419] P d2afc49f513f429cbd2f8792faeba212: Scheduling FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144): perf score=14.095187
I20260812 06:18:48.884696 32030 maintenance_manager.cc:643] P d2afc49f513f429cbd2f8792faeba212: FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144) complete. Timing: real 0.060s	user 0.044s	sys 0.013s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":26450,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:48.885375 32123 maintenance_manager.cc:419] P d2afc49f513f429cbd2f8792faeba212: Scheduling FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144): perf score=2.188937
I20260812 06:18:48.906850 32030 maintenance_manager.cc:643] P d2afc49f513f429cbd2f8792faeba212: FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144) complete. Timing: real 0.021s	user 0.009s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6466,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:48.907560 32123 maintenance_manager.cc:419] P d2afc49f513f429cbd2f8792faeba212: Scheduling MajorDeltaCompactionOp(8ce587f6acf5408d93fc1e2e2021b144): perf score=1.000000
I20260812 06:18:49.064347 32030 maintenance_manager.cc:643] P d2afc49f513f429cbd2f8792faeba212: MajorDeltaCompactionOp(8ce587f6acf5408d93fc1e2e2021b144) complete. Timing: real 0.157s	user 0.112s	sys 0.045s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":188,"lbm_read_time_us":10983,"lbm_reads_lt_1ms":564,"lbm_write_time_us":27871,"lbm_writes_lt_1ms":543,"mutex_wait_us":28,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13440,"update_count":2500}
I20260812 06:18:49.065107 32123 maintenance_manager.cc:419] P d2afc49f513f429cbd2f8792faeba212: Scheduling FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144): perf score=14.095187
I20260812 06:18:49.126338 32030 maintenance_manager.cc:643] P d2afc49f513f429cbd2f8792faeba212: FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144) complete. Timing: real 0.061s	user 0.025s	sys 0.023s Metrics: {"bytes_written":16409899,"delete_count":0,"lbm_write_time_us":22297,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:49.126883 32123 maintenance_manager.cc:419] P d2afc49f513f429cbd2f8792faeba212: Scheduling FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144): perf score=2.188937
I20260812 06:18:49.138711 32030 maintenance_manager.cc:643] P d2afc49f513f429cbd2f8792faeba212: FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144) complete. Timing: real 0.012s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4024,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:49.139925 32123 maintenance_manager.cc:419] P d2afc49f513f429cbd2f8792faeba212: Scheduling MajorDeltaCompactionOp(8ce587f6acf5408d93fc1e2e2021b144): perf score=1.000000
I20260812 06:18:49.309222 32030 maintenance_manager.cc:643] P d2afc49f513f429cbd2f8792faeba212: MajorDeltaCompactionOp(8ce587f6acf5408d93fc1e2e2021b144) complete. Timing: real 0.169s	user 0.125s	sys 0.043s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":211,"lbm_read_time_us":11382,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30797,"lbm_writes_lt_1ms":543,"mutex_wait_us":95,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4736,"update_count":2500}
I20260812 06:18:49.310034 32123 maintenance_manager.cc:419] P d2afc49f513f429cbd2f8792faeba212: Scheduling FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144): perf score=14.095187
I20260812 06:18:49.370273 32030 maintenance_manager.cc:643] P d2afc49f513f429cbd2f8792faeba212: FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144) complete. Timing: real 0.060s	user 0.038s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21650,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:49.370880 32123 maintenance_manager.cc:419] P d2afc49f513f429cbd2f8792faeba212: Scheduling FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144): perf score=2.188937
I20260812 06:18:49.382158 32030 maintenance_manager.cc:643] P d2afc49f513f429cbd2f8792faeba212: FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4468,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:49.382797 32123 maintenance_manager.cc:419] P d2afc49f513f429cbd2f8792faeba212: Scheduling FlushMRSOp(8ce587f6acf5408d93fc1e2e2021b144): perf score=1.000000
I20260812 06:18:49.414929 32030 maintenance_manager.cc:643] P d2afc49f513f429cbd2f8792faeba212: FlushMRSOp(8ce587f6acf5408d93fc1e2e2021b144) complete. Timing: real 0.032s	user 0.025s	sys 0.000s Metrics: {"bytes_written":1234477,"cfile_init":1,"dirs.queue_time_us":84,"dirs.run_cpu_time_us":251,"dirs.run_wall_time_us":1441,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1695,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:49.415680 32123 maintenance_manager.cc:419] P d2afc49f513f429cbd2f8792faeba212: Scheduling LogGCOp(8ce587f6acf5408d93fc1e2e2021b144): free 112692565 bytes of WAL
I20260812 06:18:49.415979 32030 log_reader.cc:385] T 8ce587f6acf5408d93fc1e2e2021b144: removed 11 log segments from log reader
I20260812 06:18:49.416046 32030 log.cc:1079] T 8ce587f6acf5408d93fc1e2e2021b144 P d2afc49f513f429cbd2f8792faeba212: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/8ce587f6acf5408d93fc1e2e2021b144/wal-000000028 (ops 133-137)
I20260812 06:18:49.416123 32030 log.cc:1079] T 8ce587f6acf5408d93fc1e2e2021b144 P d2afc49f513f429cbd2f8792faeba212: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/8ce587f6acf5408d93fc1e2e2021b144/wal-000000029 (ops 138-142)
I20260812 06:18:49.416160 32030 log.cc:1079] T 8ce587f6acf5408d93fc1e2e2021b144 P d2afc49f513f429cbd2f8792faeba212: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/8ce587f6acf5408d93fc1e2e2021b144/wal-000000030 (ops 143-147)
I20260812 06:18:49.416182 32030 log.cc:1079] T 8ce587f6acf5408d93fc1e2e2021b144 P d2afc49f513f429cbd2f8792faeba212: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/8ce587f6acf5408d93fc1e2e2021b144/wal-000000031 (ops 148-152)
I20260812 06:18:49.416204 32030 log.cc:1079] T 8ce587f6acf5408d93fc1e2e2021b144 P d2afc49f513f429cbd2f8792faeba212: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/8ce587f6acf5408d93fc1e2e2021b144/wal-000000032 (ops 153-157)
I20260812 06:18:49.416227 32030 log.cc:1079] T 8ce587f6acf5408d93fc1e2e2021b144 P d2afc49f513f429cbd2f8792faeba212: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/8ce587f6acf5408d93fc1e2e2021b144/wal-000000033 (ops 158-162)
I20260812 06:18:49.416262 32030 log.cc:1079] T 8ce587f6acf5408d93fc1e2e2021b144 P d2afc49f513f429cbd2f8792faeba212: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/8ce587f6acf5408d93fc1e2e2021b144/wal-000000034 (ops 163-167)
I20260812 06:18:49.416288 32030 log.cc:1079] T 8ce587f6acf5408d93fc1e2e2021b144 P d2afc49f513f429cbd2f8792faeba212: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/8ce587f6acf5408d93fc1e2e2021b144/wal-000000035 (ops 168-172)
I20260812 06:18:49.416311 32030 log.cc:1079] T 8ce587f6acf5408d93fc1e2e2021b144 P d2afc49f513f429cbd2f8792faeba212: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/8ce587f6acf5408d93fc1e2e2021b144/wal-000000036 (ops 173-177)
I20260812 06:18:49.416340 32030 log.cc:1079] T 8ce587f6acf5408d93fc1e2e2021b144 P d2afc49f513f429cbd2f8792faeba212: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/8ce587f6acf5408d93fc1e2e2021b144/wal-000000037 (ops 178-182)
I20260812 06:18:49.416369 32030 log.cc:1079] T 8ce587f6acf5408d93fc1e2e2021b144 P d2afc49f513f429cbd2f8792faeba212: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/8ce587f6acf5408d93fc1e2e2021b144/wal-000000038 (ops 183-187)
I20260812 06:18:49.444043 32030 maintenance_manager.cc:643] P d2afc49f513f429cbd2f8792faeba212: LogGCOp(8ce587f6acf5408d93fc1e2e2021b144) complete. Timing: real 0.028s	user 0.003s	sys 0.022s Metrics: {}
I20260812 06:18:49.444567 32123 maintenance_manager.cc:419] P d2afc49f513f429cbd2f8792faeba212: Scheduling UndoDeltaBlockGCOp(8ce587f6acf5408d93fc1e2e2021b144): 473 bytes on disk
I20260812 06:18:49.445057 32030 maintenance_manager.cc:643] P d2afc49f513f429cbd2f8792faeba212: UndoDeltaBlockGCOp(8ce587f6acf5408d93fc1e2e2021b144) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4}
I20260812 06:18:49.445639 32123 maintenance_manager.cc:419] P d2afc49f513f429cbd2f8792faeba212: Scheduling FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144): perf score=2.188937
I20260812 06:18:49.469231 32030 maintenance_manager.cc:643] P d2afc49f513f429cbd2f8792faeba212: FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144) complete. Timing: real 0.023s	user 0.013s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6337,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:49.469776 32123 maintenance_manager.cc:419] P d2afc49f513f429cbd2f8792faeba212: Scheduling LogGCOp(8ce587f6acf5408d93fc1e2e2021b144): free 12018004 bytes of WAL
I20260812 06:18:49.470028 32030 log_reader.cc:385] T 8ce587f6acf5408d93fc1e2e2021b144: removed 1 log segments from log reader
I20260812 06:18:49.470101 32030 log.cc:1079] T 8ce587f6acf5408d93fc1e2e2021b144 P d2afc49f513f429cbd2f8792faeba212: Deleting log segment in path: /tmp/dist-test-taskJK68vq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518923217-31566-0/minicluster-data/ts-0-root/wals/8ce587f6acf5408d93fc1e2e2021b144/wal-000000039 (ops 188-192)
I20260812 06:18:49.472505 32030 maintenance_manager.cc:643] P d2afc49f513f429cbd2f8792faeba212: LogGCOp(8ce587f6acf5408d93fc1e2e2021b144) complete. Timing: real 0.003s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:18:49.472852 32123 maintenance_manager.cc:419] P d2afc49f513f429cbd2f8792faeba212: Scheduling FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144): perf score=2.188937
I20260812 06:18:49.484054 32030 maintenance_manager.cc:643] P d2afc49f513f429cbd2f8792faeba212: FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144) complete. Timing: real 0.011s	user 0.002s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4051,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:49.484719 32123 maintenance_manager.cc:419] P d2afc49f513f429cbd2f8792faeba212: Scheduling MajorDeltaCompactionOp(8ce587f6acf5408d93fc1e2e2021b144): perf score=1.000000
I20260812 06:18:49.648792 31566 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.979s	user 1.826s	sys 0.177s
I20260812 06:18:49.703683 32030 maintenance_manager.cc:643] P d2afc49f513f429cbd2f8792faeba212: MajorDeltaCompactionOp(8ce587f6acf5408d93fc1e2e2021b144) complete. Timing: real 0.219s	user 0.160s	sys 0.055s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979750,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":15202,"lbm_reads_lt_1ms":770,"lbm_write_time_us":41610,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":742,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":3500}
I20260812 06:18:49.704264 32123 maintenance_manager.cc:419] P d2afc49f513f429cbd2f8792faeba212: Scheduling FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144): perf score=14.095187
I20260812 06:18:49.744661 31566 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.095s	user 0.004s	sys 0.000s
I20260812 06:18:49.745316 31566 tablet_server.cc:179] TabletServer@127.30.211.129:0 shutting down...
I20260812 06:18:49.745496 32030 maintenance_manager.cc:643] P d2afc49f513f429cbd2f8792faeba212: FlushDeltaMemStoresOp(8ce587f6acf5408d93fc1e2e2021b144) complete. Timing: real 0.041s	user 0.011s	sys 0.029s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18554,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:49.746166 32123 maintenance_manager.cc:419] P d2afc49f513f429cbd2f8792faeba212: Scheduling MajorDeltaCompactionOp(8ce587f6acf5408d93fc1e2e2021b144): perf score=1.000000
I20260812 06:18:49.876586 32030 maintenance_manager.cc:643] P d2afc49f513f429cbd2f8792faeba212: MajorDeltaCompactionOp(8ce587f6acf5408d93fc1e2e2021b144) complete. Timing: real 0.130s	user 0.098s	sys 0.032s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672158,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":332,"lbm_read_time_us":10979,"lbm_reads_lt_1ms":467,"lbm_write_time_us":25588,"lbm_writes_lt_1ms":443,"mutex_wait_us":44,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:49.877360 31566 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:49.877643 31566 tablet_replica.cc:333] T 8ce587f6acf5408d93fc1e2e2021b144 P d2afc49f513f429cbd2f8792faeba212: stopping tablet replica
I20260812 06:18:49.877868 31566 raft_consensus.cc:2243] T 8ce587f6acf5408d93fc1e2e2021b144 P d2afc49f513f429cbd2f8792faeba212 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:49.878059 31566 raft_consensus.cc:2272] T 8ce587f6acf5408d93fc1e2e2021b144 P d2afc49f513f429cbd2f8792faeba212 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:49.882970 31566 tablet_server.cc:196] TabletServer@127.30.211.129:0 shutdown complete.
I20260812 06:18:49.938707 31566 master.cc:562] Master@127.30.211.190:43787 shutting down...
I20260812 06:18:49.943065 31566 raft_consensus.cc:2243] T 00000000000000000000000000000000 P eb5c4ccdd5a346aa86bc74194bf072ea [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:49.943300 31566 raft_consensus.cc:2272] T 00000000000000000000000000000000 P eb5c4ccdd5a346aa86bc74194bf072ea [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:49.943378 31566 tablet_replica.cc:333] T 00000000000000000000000000000000 P eb5c4ccdd5a346aa86bc74194bf072ea: stopping tablet replica
I20260812 06:18:49.956008 31566 master.cc:584] Master@127.30.211.190:43787 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5577 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11113 ms total)

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