[==========] 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:17:47.065397 19929 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.19.118.126:46589
I20260812 06:17:47.066488 19929 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:17:47.067114 19929 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:47.073659 19938 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:17:47.073664 19937 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:17:47.073895 19929 server_base.cc:1061] running on GCE node
W20260812 06:17:47.073937 19942 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:17:47.074451 19929 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:47.074553 19929 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:17:47.074586 19929 hybrid_clock.cc:648] HybridClock initialized: now 1786515467074585 us; error 0 us; skew 500 ppm
I20260812 06:17:47.076481 19929 webserver.cc:533] Webserver started at http://127.19.118.126:34575/ using document root <none> and password file <none>
I20260812 06:17:47.077019 19929 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:47.077077 19929 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:47.077286 19929 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:47.078918 19929 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515467054230-19929-0/minicluster-data/master-0-root/instance:
uuid: "a94be9e0924542ac9021974cd76b2ce1"
format_stamp: "Formatted at 2026-08-12 06:17:47 on dist-test-slave-1l3l"
I20260812 06:17:47.082540 19929 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.005s	sys 0.000s
I20260812 06:17:47.084704 19955 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:17:47.085700 19929 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:47.085808 19929 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515467054230-19929-0/minicluster-data/master-0-root
uuid: "a94be9e0924542ac9021974cd76b2ce1"
format_stamp: "Formatted at 2026-08-12 06:17:47 on dist-test-slave-1l3l"
I20260812 06:17:47.085891 19929 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515467054230-19929-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515467054230-19929-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515467054230-19929-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:17:47.107249 19929 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:47.107992 19929 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:17:47.108143 19929 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:47.116204 20043 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.19.118.126:46589 every 8 connection(s)
I20260812 06:17:47.116214 19929 rpc_server.cc:307] RPC server started. Bound to: 127.19.118.126:46589
I20260812 06:17:47.118716 20044 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:17:47.124485 20044 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a94be9e0924542ac9021974cd76b2ce1: Bootstrap starting.
I20260812 06:17:47.126940 20044 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P a94be9e0924542ac9021974cd76b2ce1: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:47.127952 20044 log.cc:826] T 00000000000000000000000000000000 P a94be9e0924542ac9021974cd76b2ce1: Log is configured to *not* fsync() on all Append() calls
I20260812 06:17:47.129860 20044 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a94be9e0924542ac9021974cd76b2ce1: No bootstrap required, opened a new log
I20260812 06:17:47.132925 20044 raft_consensus.cc:359] T 00000000000000000000000000000000 P a94be9e0924542ac9021974cd76b2ce1 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a94be9e0924542ac9021974cd76b2ce1" member_type: VOTER }
I20260812 06:17:47.133117 20044 raft_consensus.cc:385] T 00000000000000000000000000000000 P a94be9e0924542ac9021974cd76b2ce1 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:47.133160 20044 raft_consensus.cc:740] T 00000000000000000000000000000000 P a94be9e0924542ac9021974cd76b2ce1 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: a94be9e0924542ac9021974cd76b2ce1, State: Initialized, Role: FOLLOWER
I20260812 06:17:47.133801 20044 consensus_queue.cc:260] T 00000000000000000000000000000000 P a94be9e0924542ac9021974cd76b2ce1 [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: "a94be9e0924542ac9021974cd76b2ce1" member_type: VOTER }
I20260812 06:17:47.133955 20044 raft_consensus.cc:399] T 00000000000000000000000000000000 P a94be9e0924542ac9021974cd76b2ce1 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:47.134030 20044 raft_consensus.cc:493] T 00000000000000000000000000000000 P a94be9e0924542ac9021974cd76b2ce1 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:47.134155 20044 raft_consensus.cc:3060] T 00000000000000000000000000000000 P a94be9e0924542ac9021974cd76b2ce1 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:47.134985 20044 raft_consensus.cc:515] T 00000000000000000000000000000000 P a94be9e0924542ac9021974cd76b2ce1 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a94be9e0924542ac9021974cd76b2ce1" member_type: VOTER }
I20260812 06:17:47.135459 20044 leader_election.cc:304] T 00000000000000000000000000000000 P a94be9e0924542ac9021974cd76b2ce1 [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: a94be9e0924542ac9021974cd76b2ce1; no voters: 
I20260812 06:17:47.135830 20044 leader_election.cc:290] T 00000000000000000000000000000000 P a94be9e0924542ac9021974cd76b2ce1 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:47.136185 20048 raft_consensus.cc:2804] T 00000000000000000000000000000000 P a94be9e0924542ac9021974cd76b2ce1 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:47.136477 20048 raft_consensus.cc:697] T 00000000000000000000000000000000 P a94be9e0924542ac9021974cd76b2ce1 [term 1 LEADER]: Becoming Leader. State: Replica: a94be9e0924542ac9021974cd76b2ce1, State: Running, Role: LEADER
I20260812 06:17:47.136847 20048 consensus_queue.cc:237] T 00000000000000000000000000000000 P a94be9e0924542ac9021974cd76b2ce1 [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: "a94be9e0924542ac9021974cd76b2ce1" member_type: VOTER }
I20260812 06:17:47.136994 20044 sys_catalog.cc:565] T 00000000000000000000000000000000 P a94be9e0924542ac9021974cd76b2ce1 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:47.138779 20051 sys_catalog.cc:455] T 00000000000000000000000000000000 P a94be9e0924542ac9021974cd76b2ce1 [sys.catalog]: SysCatalogTable state changed. Reason: New leader a94be9e0924542ac9021974cd76b2ce1. Latest consensus state: current_term: 1 leader_uuid: "a94be9e0924542ac9021974cd76b2ce1" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a94be9e0924542ac9021974cd76b2ce1" member_type: VOTER } }
I20260812 06:17:47.138816 20050 sys_catalog.cc:455] T 00000000000000000000000000000000 P a94be9e0924542ac9021974cd76b2ce1 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "a94be9e0924542ac9021974cd76b2ce1" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a94be9e0924542ac9021974cd76b2ce1" member_type: VOTER } }
I20260812 06:17:47.138916 20050 sys_catalog.cc:458] T 00000000000000000000000000000000 P a94be9e0924542ac9021974cd76b2ce1 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:47.138917 20051 sys_catalog.cc:458] T 00000000000000000000000000000000 P a94be9e0924542ac9021974cd76b2ce1 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:47.139391 19929 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:17:47.141355 20075 catalog_manager.cc:1594] T 00000000000000000000000000000000 P a94be9e0924542ac9021974cd76b2ce1: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:17:47.141422 20075 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:17:47.141496 20071 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:47.142212 20071 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:47.147526 20071 catalog_manager.cc:1383] Generated new cluster ID: 5761e5d88e754d91bee6537147ea1b58
I20260812 06:17:47.147603 20071 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:47.157868 20071 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:47.159073 20071 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:47.174281 20071 catalog_manager.cc:6092] T 00000000000000000000000000000000 P a94be9e0924542ac9021974cd76b2ce1: Generated new TSK 0
I20260812 06:17:47.175163 20071 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:47.204542 19929 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:47.207283 20080 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:17:47.207304 20083 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:17:47.207329 20081 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:17:47.207756 19929 server_base.cc:1061] running on GCE node
I20260812 06:17:47.207942 19929 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:47.207990 19929 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:17:47.208019 19929 hybrid_clock.cc:648] HybridClock initialized: now 1786515467208018 us; error 0 us; skew 500 ppm
I20260812 06:17:47.208992 19929 webserver.cc:533] Webserver started at http://127.19.118.65:45543/ using document root <none> and password file <none>
I20260812 06:17:47.209167 19929 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:47.209225 19929 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:47.209300 19929 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:47.209750 19929 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515467054230-19929-0/minicluster-data/ts-0-root/instance:
uuid: "4be7c193b4d24288a282ad958d6856f7"
format_stamp: "Formatted at 2026-08-12 06:17:47 on dist-test-slave-1l3l"
I20260812 06:17:47.211638 19929 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:47.212790 20091 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:17:47.213068 19929 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:47.213146 19929 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515467054230-19929-0/minicluster-data/ts-0-root
uuid: "4be7c193b4d24288a282ad958d6856f7"
format_stamp: "Formatted at 2026-08-12 06:17:47 on dist-test-slave-1l3l"
I20260812 06:17:47.213222 19929 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515467054230-19929-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515467054230-19929-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515467054230-19929-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:17:47.240819 19929 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:47.241840 19929 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:47.242408 19929 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:47.243459 19929 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:47.243527 19929 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:47.243587 19929 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:47.243618 19929 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:47.250656 19929 rpc_server.cc:307] RPC server started. Bound to: 127.19.118.65:38445
I20260812 06:17:47.250710 20197 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.19.118.65:38445 every 8 connection(s)
I20260812 06:17:47.263579 20199 heartbeater.cc:344] Connected to a master server at 127.19.118.126:46589
I20260812 06:17:47.263862 20199 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:47.264320 20199 heartbeater.cc:507] Master 127.19.118.126:46589 requested a full tablet report, sending...
I20260812 06:17:47.265753 19988 ts_manager.cc:194] Registered new tserver with Master: 4be7c193b4d24288a282ad958d6856f7 (127.19.118.65:38445)
I20260812 06:17:47.265846 19929 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.014508072s
I20260812 06:17:47.266948 19988 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:49662
I20260812 06:17:47.275694 19988 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:49668:
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:17:47.292054 20139 tablet_service.cc:1511] Processing CreateTablet for tablet b7ac1ab8d9b242d7841094a3494ba03c (DEFAULT_TABLE table=heavy-update-compaction-test [id=0710509497544ff7a347339e9b144436]), partition=
I20260812 06:17:47.292582 20139 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet b7ac1ab8d9b242d7841094a3494ba03c. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:47.295558 20221 tablet_bootstrap.cc:492] T b7ac1ab8d9b242d7841094a3494ba03c P 4be7c193b4d24288a282ad958d6856f7: Bootstrap starting.
I20260812 06:17:47.297036 20221 tablet_bootstrap.cc:654] T b7ac1ab8d9b242d7841094a3494ba03c P 4be7c193b4d24288a282ad958d6856f7: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:47.298521 20221 tablet_bootstrap.cc:492] T b7ac1ab8d9b242d7841094a3494ba03c P 4be7c193b4d24288a282ad958d6856f7: No bootstrap required, opened a new log
I20260812 06:17:47.298626 20221 ts_tablet_manager.cc:1403] T b7ac1ab8d9b242d7841094a3494ba03c P 4be7c193b4d24288a282ad958d6856f7: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:17:47.299098 20221 raft_consensus.cc:359] T b7ac1ab8d9b242d7841094a3494ba03c P 4be7c193b4d24288a282ad958d6856f7 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4be7c193b4d24288a282ad958d6856f7" member_type: VOTER last_known_addr { host: "127.19.118.65" port: 38445 } }
I20260812 06:17:47.299206 20221 raft_consensus.cc:385] T b7ac1ab8d9b242d7841094a3494ba03c P 4be7c193b4d24288a282ad958d6856f7 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:47.299238 20221 raft_consensus.cc:740] T b7ac1ab8d9b242d7841094a3494ba03c P 4be7c193b4d24288a282ad958d6856f7 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 4be7c193b4d24288a282ad958d6856f7, State: Initialized, Role: FOLLOWER
I20260812 06:17:47.299376 20221 consensus_queue.cc:260] T b7ac1ab8d9b242d7841094a3494ba03c P 4be7c193b4d24288a282ad958d6856f7 [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: "4be7c193b4d24288a282ad958d6856f7" member_type: VOTER last_known_addr { host: "127.19.118.65" port: 38445 } }
I20260812 06:17:47.299458 20221 raft_consensus.cc:399] T b7ac1ab8d9b242d7841094a3494ba03c P 4be7c193b4d24288a282ad958d6856f7 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:47.299484 20221 raft_consensus.cc:493] T b7ac1ab8d9b242d7841094a3494ba03c P 4be7c193b4d24288a282ad958d6856f7 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:47.299513 20221 raft_consensus.cc:3060] T b7ac1ab8d9b242d7841094a3494ba03c P 4be7c193b4d24288a282ad958d6856f7 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:47.300312 20221 raft_consensus.cc:515] T b7ac1ab8d9b242d7841094a3494ba03c P 4be7c193b4d24288a282ad958d6856f7 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4be7c193b4d24288a282ad958d6856f7" member_type: VOTER last_known_addr { host: "127.19.118.65" port: 38445 } }
I20260812 06:17:47.300441 20221 leader_election.cc:304] T b7ac1ab8d9b242d7841094a3494ba03c P 4be7c193b4d24288a282ad958d6856f7 [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: 4be7c193b4d24288a282ad958d6856f7; no voters: 
I20260812 06:17:47.300631 20221 leader_election.cc:290] T b7ac1ab8d9b242d7841094a3494ba03c P 4be7c193b4d24288a282ad958d6856f7 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:47.300794 20223 raft_consensus.cc:2804] T b7ac1ab8d9b242d7841094a3494ba03c P 4be7c193b4d24288a282ad958d6856f7 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:47.300944 20221 ts_tablet_manager.cc:1434] T b7ac1ab8d9b242d7841094a3494ba03c P 4be7c193b4d24288a282ad958d6856f7: Time spent starting tablet: real 0.002s	user 0.001s	sys 0.001s
I20260812 06:17:47.301077 20223 raft_consensus.cc:697] T b7ac1ab8d9b242d7841094a3494ba03c P 4be7c193b4d24288a282ad958d6856f7 [term 1 LEADER]: Becoming Leader. State: Replica: 4be7c193b4d24288a282ad958d6856f7, State: Running, Role: LEADER
I20260812 06:17:47.301209 20199 heartbeater.cc:499] Master 127.19.118.126:46589 was elected leader, sending a full tablet report...
I20260812 06:17:47.301224 20223 consensus_queue.cc:237] T b7ac1ab8d9b242d7841094a3494ba03c P 4be7c193b4d24288a282ad958d6856f7 [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: "4be7c193b4d24288a282ad958d6856f7" member_type: VOTER last_known_addr { host: "127.19.118.65" port: 38445 } }
I20260812 06:17:47.303985 19988 catalog_manager.cc:5719] T b7ac1ab8d9b242d7841094a3494ba03c P 4be7c193b4d24288a282ad958d6856f7 reported cstate change: term changed from 0 to 1, leader changed from <none> to 4be7c193b4d24288a282ad958d6856f7 (127.19.118.65). New cstate: current_term: 1 leader_uuid: "4be7c193b4d24288a282ad958d6856f7" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4be7c193b4d24288a282ad958d6856f7" member_type: VOTER last_known_addr { host: "127.19.118.65" port: 38445 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:47.364507 19929 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.054s	user 0.019s	sys 0.004s
I20260812 06:17:47.501812 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling FlushMRSOp(b7ac1ab8d9b242d7841094a3494ba03c): perf score=19.054940
I20260812 06:17:47.687521 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: FlushMRSOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.185s	user 0.145s	sys 0.028s Metrics: {"bytes_written":12307490,"cfile_init":1,"compiler_manager_pool.queue_time_us":241,"delete_count":0,"dirs.queue_time_us":71,"dirs.run_cpu_time_us":254,"dirs.run_wall_time_us":846,"drs_written":1,"lbm_read_time_us":79,"lbm_reads_lt_1ms":4,"lbm_write_time_us":43641,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":756,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":129,"threads_started":1,"update_count":1500}
I20260812 06:17:47.688866 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling LogGCOp(b7ac1ab8d9b242d7841094a3494ba03c): free 20743880 bytes of WAL
I20260812 06:17:47.689213 20101 log_reader.cc:385] T b7ac1ab8d9b242d7841094a3494ba03c: removed 2 log segments from log reader
I20260812 06:17:47.689294 20101 log.cc:1079] T b7ac1ab8d9b242d7841094a3494ba03c P 4be7c193b4d24288a282ad958d6856f7: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/b7ac1ab8d9b242d7841094a3494ba03c/wal-000000001 (ops 1-6)
I20260812 06:17:47.689354 20101 log.cc:1079] T b7ac1ab8d9b242d7841094a3494ba03c P 4be7c193b4d24288a282ad958d6856f7: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/b7ac1ab8d9b242d7841094a3494ba03c/wal-000000002 (ops 7-11)
I20260812 06:17:47.695271 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: LogGCOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.006s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:17:47.695909 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling UndoDeltaBlockGCOp(b7ac1ab8d9b242d7841094a3494ba03c): 16411392 bytes on disk
I20260812 06:17:47.696687 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: UndoDeltaBlockGCOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":86,"lbm_reads_lt_1ms":4}
I20260812 06:17:47.697285 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c): perf score=2.188937
I20260812 06:17:47.712086 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.014s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4030,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:47.712576 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling MajorDeltaCompactionOp(b7ac1ab8d9b242d7841094a3494ba03c): perf score=1.000000
I20260812 06:17:47.851755 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: MajorDeltaCompactionOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.139s	user 0.091s	sys 0.045s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":506,"lbm_read_time_us":7446,"lbm_reads_lt_1ms":460,"lbm_write_time_us":23550,"lbm_writes_lt_1ms":443,"mutex_wait_us":97,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":19712,"thread_start_us":409,"threads_started":5,"update_count":2000}
I20260812 06:17:47.852360 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c): perf score=10.126437
I20260812 06:17:47.886925 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.034s	user 0.026s	sys 0.003s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":13731,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:47.887415 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c): perf score=2.188937
I20260812 06:17:47.898001 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3773,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:47.898569 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling MajorDeltaCompactionOp(b7ac1ab8d9b242d7841094a3494ba03c): perf score=1.000000
I20260812 06:17:48.018675 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: MajorDeltaCompactionOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.120s	user 0.083s	sys 0.037s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672275,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":334,"lbm_read_time_us":7879,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23495,"lbm_writes_lt_1ms":443,"mutex_wait_us":42,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":32000,"update_count":2000}
I20260812 06:17:48.019227 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c): perf score=10.126437
I20260812 06:17:48.052023 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.033s	user 0.025s	sys 0.007s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":13991,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:48.052541 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling MajorDeltaCompactionOp(b7ac1ab8d9b242d7841094a3494ba03c): perf score=1.000000
I20260812 06:17:48.165707 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: MajorDeltaCompactionOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.113s	user 0.087s	sys 0.024s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569747,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":930,"lbm_read_time_us":6498,"lbm_reads_lt_1ms":363,"lbm_write_time_us":21428,"lbm_writes_lt_1ms":343,"mutex_wait_us":302,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":1500}
I20260812 06:17:48.166221 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c): perf score=10.126437
I20260812 06:17:48.210875 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.045s	user 0.023s	sys 0.007s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14094,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:48.211405 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c): perf score=2.188937
I20260812 06:17:48.222240 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3744,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:48.222899 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling MajorDeltaCompactionOp(b7ac1ab8d9b242d7841094a3494ba03c): perf score=1.000000
I20260812 06:17:48.350883 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: MajorDeltaCompactionOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.128s	user 0.100s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":930,"lbm_read_time_us":8141,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22979,"lbm_writes_lt_1ms":443,"mutex_wait_us":337,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":15616,"update_count":2000}
I20260812 06:17:48.351457 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c): perf score=10.126437
I20260812 06:17:48.394428 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.043s	user 0.027s	sys 0.004s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14084,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:48.394999 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c): perf score=2.188937
I20260812 06:17:48.406349 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3926,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:48.407024 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling MajorDeltaCompactionOp(b7ac1ab8d9b242d7841094a3494ba03c): perf score=1.000000
I20260812 06:17:48.532529 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: MajorDeltaCompactionOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.125s	user 0.106s	sys 0.019s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":290,"lbm_read_time_us":7961,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23842,"lbm_writes_lt_1ms":443,"mutex_wait_us":73,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":24320,"update_count":2000}
I20260812 06:17:48.533185 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c): perf score=10.126437
I20260812 06:17:48.581817 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.048s	user 0.026s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17434,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:48.582463 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c): perf score=2.188937
I20260812 06:17:48.598413 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.016s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5680,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:48.598932 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling MajorDeltaCompactionOp(b7ac1ab8d9b242d7841094a3494ba03c): perf score=1.000000
I20260812 06:17:48.725188 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: MajorDeltaCompactionOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.126s	user 0.084s	sys 0.042s 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":303,"lbm_read_time_us":9392,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23392,"lbm_writes_lt_1ms":443,"mutex_wait_us":53,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:48.725791 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c): perf score=10.126437
I20260812 06:17:48.775504 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.049s	user 0.024s	sys 0.013s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":14173,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:48.776224 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c): perf score=2.188937
I20260812 06:17:48.792320 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.016s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6016,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:48.792951 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling MajorDeltaCompactionOp(b7ac1ab8d9b242d7841094a3494ba03c): perf score=1.000000
I20260812 06:17:48.931314 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: MajorDeltaCompactionOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.138s	user 0.102s	sys 0.036s 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":276,"lbm_read_time_us":11524,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21903,"lbm_writes_lt_1ms":443,"mutex_wait_us":55,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2000}
I20260812 06:17:48.932094 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c): perf score=10.126437
I20260812 06:17:48.978010 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.046s	user 0.027s	sys 0.005s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14554,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:48.978552 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c): perf score=2.188937
I20260812 06:17:48.989568 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4012,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:48.990396 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling FlushMRSOp(b7ac1ab8d9b242d7841094a3494ba03c): perf score=1.000000
I20260812 06:17:49.019028 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: FlushMRSOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.028s	user 0.026s	sys 0.000s Metrics: {"bytes_written":1275443,"cfile_init":1,"dirs.queue_time_us":82,"dirs.run_cpu_time_us":264,"dirs.run_wall_time_us":1683,"drs_written":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1589,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:49.020058 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling LogGCOp(b7ac1ab8d9b242d7841094a3494ba03c): free 121006431 bytes of WAL
I20260812 06:17:49.020340 20101 log_reader.cc:385] T b7ac1ab8d9b242d7841094a3494ba03c: removed 12 log segments from log reader
I20260812 06:17:49.020411 20101 log.cc:1079] T b7ac1ab8d9b242d7841094a3494ba03c P 4be7c193b4d24288a282ad958d6856f7: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/b7ac1ab8d9b242d7841094a3494ba03c/wal-000000003 (ops 12-16)
I20260812 06:17:49.020466 20101 log.cc:1079] T b7ac1ab8d9b242d7841094a3494ba03c P 4be7c193b4d24288a282ad958d6856f7: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/b7ac1ab8d9b242d7841094a3494ba03c/wal-000000004 (ops 17-20)
I20260812 06:17:49.020495 20101 log.cc:1079] T b7ac1ab8d9b242d7841094a3494ba03c P 4be7c193b4d24288a282ad958d6856f7: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/b7ac1ab8d9b242d7841094a3494ba03c/wal-000000005 (ops 21-25)
I20260812 06:17:49.020526 20101 log.cc:1079] T b7ac1ab8d9b242d7841094a3494ba03c P 4be7c193b4d24288a282ad958d6856f7: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/b7ac1ab8d9b242d7841094a3494ba03c/wal-000000006 (ops 26-30)
I20260812 06:17:49.020558 20101 log.cc:1079] T b7ac1ab8d9b242d7841094a3494ba03c P 4be7c193b4d24288a282ad958d6856f7: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/b7ac1ab8d9b242d7841094a3494ba03c/wal-000000007 (ops 31-35)
I20260812 06:17:49.020591 20101 log.cc:1079] T b7ac1ab8d9b242d7841094a3494ba03c P 4be7c193b4d24288a282ad958d6856f7: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/b7ac1ab8d9b242d7841094a3494ba03c/wal-000000008 (ops 36-40)
I20260812 06:17:49.020620 20101 log.cc:1079] T b7ac1ab8d9b242d7841094a3494ba03c P 4be7c193b4d24288a282ad958d6856f7: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/b7ac1ab8d9b242d7841094a3494ba03c/wal-000000009 (ops 41-45)
I20260812 06:17:49.020648 20101 log.cc:1079] T b7ac1ab8d9b242d7841094a3494ba03c P 4be7c193b4d24288a282ad958d6856f7: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/b7ac1ab8d9b242d7841094a3494ba03c/wal-000000010 (ops 46-50)
I20260812 06:17:49.020676 20101 log.cc:1079] T b7ac1ab8d9b242d7841094a3494ba03c P 4be7c193b4d24288a282ad958d6856f7: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/b7ac1ab8d9b242d7841094a3494ba03c/wal-000000011 (ops 51-55)
I20260812 06:17:49.020700 20101 log.cc:1079] T b7ac1ab8d9b242d7841094a3494ba03c P 4be7c193b4d24288a282ad958d6856f7: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/b7ac1ab8d9b242d7841094a3494ba03c/wal-000000012 (ops 56-60)
I20260812 06:17:49.020726 20101 log.cc:1079] T b7ac1ab8d9b242d7841094a3494ba03c P 4be7c193b4d24288a282ad958d6856f7: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/b7ac1ab8d9b242d7841094a3494ba03c/wal-000000013 (ops 61-65)
I20260812 06:17:49.020749 20101 log.cc:1079] T b7ac1ab8d9b242d7841094a3494ba03c P 4be7c193b4d24288a282ad958d6856f7: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/b7ac1ab8d9b242d7841094a3494ba03c/wal-000000014 (ops 66-70)
I20260812 06:17:49.048259 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: LogGCOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.028s	user 0.000s	sys 0.028s Metrics: {}
I20260812 06:17:49.048820 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c): perf score=3.181125
I20260812 06:17:49.070964 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.022s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4140,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:49.071610 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c): perf score=2.188937
I20260812 06:17:49.081590 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3509,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:49.082221 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling MajorDeltaCompactionOp(b7ac1ab8d9b242d7841094a3494ba03c): perf score=1.000000
I20260812 06:17:49.292507 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: MajorDeltaCompactionOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.210s	user 0.128s	sys 0.068s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877329,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":884,"lbm_read_time_us":15150,"lbm_reads_lt_1ms":674,"lbm_write_time_us":33892,"lbm_writes_lt_1ms":643,"mutex_wait_us":23,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":5376,"thread_start_us":89,"threads_started":1,"update_count":3000}
I20260812 06:17:49.293182 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c): perf score=14.095187
I20260812 06:17:49.352866 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.059s	user 0.031s	sys 0.024s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":20053,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:17:49.353586 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c): perf score=2.188937
I20260812 06:17:49.364635 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4028,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:49.365150 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling MajorDeltaCompactionOp(b7ac1ab8d9b242d7841094a3494ba03c): perf score=1.000000
I20260812 06:17:49.542124 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: MajorDeltaCompactionOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.177s	user 0.114s	sys 0.059s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1229,"lbm_read_time_us":12059,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27899,"lbm_writes_lt_1ms":543,"mutex_wait_us":348,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:49.542677 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling UndoDeltaBlockGCOp(b7ac1ab8d9b242d7841094a3494ba03c): 482 bytes on disk
I20260812 06:17:49.543190 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: UndoDeltaBlockGCOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4}
I20260812 06:17:49.543787 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c): perf score=11.118625
I20260812 06:17:49.573335 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.029s	user 0.027s	sys 0.001s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":12248,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:49.573841 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c): perf score=2.188937
I20260812 06:17:49.591140 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.017s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5666,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:49.591765 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling MajorDeltaCompactionOp(b7ac1ab8d9b242d7841094a3494ba03c): perf score=1.000000
I20260812 06:17:49.721916 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: MajorDeltaCompactionOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.130s	user 0.092s	sys 0.037s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":762,"lbm_read_time_us":9295,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23652,"lbm_writes_lt_1ms":443,"mutex_wait_us":361,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:17:49.722628 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c): perf score=10.126437
I20260812 06:17:49.757261 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.033s	user 0.019s	sys 0.008s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":11930,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:49.757925 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c): perf score=2.188937
I20260812 06:17:49.768867 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.011s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3779,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:49.769469 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling MajorDeltaCompactionOp(b7ac1ab8d9b242d7841094a3494ba03c): perf score=1.000000
I20260812 06:17:49.894212 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: MajorDeltaCompactionOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.125s	user 0.103s	sys 0.021s 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":309,"lbm_read_time_us":8355,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25205,"lbm_writes_lt_1ms":443,"mutex_wait_us":22,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":15616,"update_count":2000}
I20260812 06:17:49.894760 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c): perf score=10.126437
I20260812 06:17:49.938390 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.043s	user 0.025s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20841,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":300,"reinsert_count":0,"update_count":1500}
I20260812 06:17:49.938967 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c): perf score=2.188937
I20260812 06:17:49.950518 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3940,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:49.951020 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling MajorDeltaCompactionOp(b7ac1ab8d9b242d7841094a3494ba03c): perf score=1.000000
I20260812 06:17:50.069471 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: MajorDeltaCompactionOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.118s	user 0.089s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":324,"lbm_read_time_us":8352,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23742,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:50.069967 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c): perf score=10.126437
I20260812 06:17:50.119104 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.049s	user 0.014s	sys 0.027s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16150,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":1500}
I20260812 06:17:50.119657 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c): perf score=2.188937
I20260812 06:17:50.129870 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3772,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:50.130404 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling MajorDeltaCompactionOp(b7ac1ab8d9b242d7841094a3494ba03c): perf score=1.000000
I20260812 06:17:50.272176 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: MajorDeltaCompactionOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.142s	user 0.109s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1106,"lbm_read_time_us":10375,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21828,"lbm_writes_lt_1ms":443,"mutex_wait_us":322,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":2000}
I20260812 06:17:50.272662 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c): perf score=10.126437
I20260812 06:17:50.315841 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.043s	user 0.028s	sys 0.008s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16001,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:50.316387 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c): perf score=2.188937
I20260812 06:17:50.326467 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3734,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:50.327004 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling MajorDeltaCompactionOp(b7ac1ab8d9b242d7841094a3494ba03c): perf score=1.000000
I20260812 06:17:50.446136 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: MajorDeltaCompactionOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.119s	user 0.091s	sys 0.028s 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":120,"lbm_read_time_us":8363,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22720,"lbm_writes_lt_1ms":443,"mutex_wait_us":21,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":28032,"update_count":2000}
I20260812 06:17:50.446619 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c): perf score=10.126437
I20260812 06:17:50.487993 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.041s	user 0.019s	sys 0.012s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":13616,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":1500}
I20260812 06:17:50.488497 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c): perf score=2.188937
I20260812 06:17:50.498337 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3793,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:50.498867 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling FlushMRSOp(b7ac1ab8d9b242d7841094a3494ba03c): perf score=1.000000
I20260812 06:17:50.531327 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: FlushMRSOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.032s	user 0.026s	sys 0.003s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":69,"dirs.run_cpu_time_us":275,"dirs.run_wall_time_us":1205,"drs_written":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2070,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:50.532188 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling LogGCOp(b7ac1ab8d9b242d7841094a3494ba03c): free 136275199 bytes of WAL
I20260812 06:17:50.532435 20101 log_reader.cc:385] T b7ac1ab8d9b242d7841094a3494ba03c: removed 13 log segments from log reader
I20260812 06:17:50.532482 20101 log.cc:1079] T b7ac1ab8d9b242d7841094a3494ba03c P 4be7c193b4d24288a282ad958d6856f7: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/b7ac1ab8d9b242d7841094a3494ba03c/wal-000000015 (ops 71-75)
I20260812 06:17:50.532510 20101 log.cc:1079] T b7ac1ab8d9b242d7841094a3494ba03c P 4be7c193b4d24288a282ad958d6856f7: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/b7ac1ab8d9b242d7841094a3494ba03c/wal-000000016 (ops 76-80)
I20260812 06:17:50.532527 20101 log.cc:1079] T b7ac1ab8d9b242d7841094a3494ba03c P 4be7c193b4d24288a282ad958d6856f7: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/b7ac1ab8d9b242d7841094a3494ba03c/wal-000000017 (ops 81-85)
I20260812 06:17:50.532557 20101 log.cc:1079] T b7ac1ab8d9b242d7841094a3494ba03c P 4be7c193b4d24288a282ad958d6856f7: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/b7ac1ab8d9b242d7841094a3494ba03c/wal-000000018 (ops 86-90)
I20260812 06:17:50.532589 20101 log.cc:1079] T b7ac1ab8d9b242d7841094a3494ba03c P 4be7c193b4d24288a282ad958d6856f7: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/b7ac1ab8d9b242d7841094a3494ba03c/wal-000000019 (ops 91-95)
I20260812 06:17:50.532608 20101 log.cc:1079] T b7ac1ab8d9b242d7841094a3494ba03c P 4be7c193b4d24288a282ad958d6856f7: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/b7ac1ab8d9b242d7841094a3494ba03c/wal-000000020 (ops 96-100)
I20260812 06:17:50.532637 20101 log.cc:1079] T b7ac1ab8d9b242d7841094a3494ba03c P 4be7c193b4d24288a282ad958d6856f7: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/b7ac1ab8d9b242d7841094a3494ba03c/wal-000000021 (ops 101-105)
I20260812 06:17:50.532670 20101 log.cc:1079] T b7ac1ab8d9b242d7841094a3494ba03c P 4be7c193b4d24288a282ad958d6856f7: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/b7ac1ab8d9b242d7841094a3494ba03c/wal-000000022 (ops 106-110)
I20260812 06:17:50.532701 20101 log.cc:1079] T b7ac1ab8d9b242d7841094a3494ba03c P 4be7c193b4d24288a282ad958d6856f7: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/b7ac1ab8d9b242d7841094a3494ba03c/wal-000000023 (ops 111-115)
I20260812 06:17:50.532733 20101 log.cc:1079] T b7ac1ab8d9b242d7841094a3494ba03c P 4be7c193b4d24288a282ad958d6856f7: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/b7ac1ab8d9b242d7841094a3494ba03c/wal-000000024 (ops 116-120)
I20260812 06:17:50.532764 20101 log.cc:1079] T b7ac1ab8d9b242d7841094a3494ba03c P 4be7c193b4d24288a282ad958d6856f7: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/b7ac1ab8d9b242d7841094a3494ba03c/wal-000000025 (ops 121-124)
I20260812 06:17:50.532796 20101 log.cc:1079] T b7ac1ab8d9b242d7841094a3494ba03c P 4be7c193b4d24288a282ad958d6856f7: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/b7ac1ab8d9b242d7841094a3494ba03c/wal-000000026 (ops 125-129)
I20260812 06:17:50.532828 20101 log.cc:1079] T b7ac1ab8d9b242d7841094a3494ba03c P 4be7c193b4d24288a282ad958d6856f7: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/b7ac1ab8d9b242d7841094a3494ba03c/wal-000000027 (ops 130-134)
I20260812 06:17:50.557396 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: LogGCOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.025s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:17:50.557927 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c): perf score=3.181125
I20260812 06:17:50.571027 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.013s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":3861,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:50.571424 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c): perf score=2.188937
I20260812 06:17:50.580227 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3293,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:50.580613 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling MajorDeltaCompactionOp(b7ac1ab8d9b242d7841094a3494ba03c): perf score=1.000000
I20260812 06:17:50.737746 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: MajorDeltaCompactionOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.157s	user 0.129s	sys 0.024s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877330,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":111,"lbm_read_time_us":12383,"lbm_reads_lt_1ms":674,"lbm_write_time_us":29132,"lbm_writes_lt_1ms":643,"mutex_wait_us":32,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":7680,"thread_start_us":72,"threads_started":1,"update_count":3000}
I20260812 06:17:50.738268 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling UndoDeltaBlockGCOp(b7ac1ab8d9b242d7841094a3494ba03c): 482 bytes on disk
I20260812 06:17:50.739319 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: UndoDeltaBlockGCOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4}
I20260812 06:17:50.739840 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c): perf score=14.095187
I20260812 06:17:50.785248 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.045s	user 0.027s	sys 0.008s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":15758,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:50.785707 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c): perf score=2.188937
I20260812 06:17:50.800587 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.015s	user 0.004s	sys 0.010s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5640,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:50.801072 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling MajorDeltaCompactionOp(b7ac1ab8d9b242d7841094a3494ba03c): perf score=1.000000
I20260812 06:17:50.942058 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: MajorDeltaCompactionOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.141s	user 0.090s	sys 0.042s 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":154,"lbm_read_time_us":8487,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25474,"lbm_writes_lt_1ms":543,"mutex_wait_us":25,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8064,"update_count":2500}
I20260812 06:17:50.942516 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c): perf score=14.095187
I20260812 06:17:50.983263 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.041s	user 0.016s	sys 0.020s Metrics: {"bytes_written":16409906,"delete_count":0,"lbm_write_time_us":17066,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:50.983739 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling MajorDeltaCompactionOp(b7ac1ab8d9b242d7841094a3494ba03c): perf score=1.000000
I20260812 06:17:51.113862 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: MajorDeltaCompactionOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.130s	user 0.097s	sys 0.032s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672162,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":862,"lbm_read_time_us":9689,"lbm_reads_lt_1ms":463,"lbm_write_time_us":20958,"lbm_writes_lt_1ms":443,"mutex_wait_us":280,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5376,"update_count":2000}
I20260812 06:17:51.114547 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c): perf score=11.118625
I20260812 06:17:51.150439 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.036s	user 0.021s	sys 0.012s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15415,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:51.151034 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c): perf score=2.188937
I20260812 06:17:51.165782 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.015s	user 0.002s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4110,"lbm_writes_lt_1ms":93,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":450}
I20260812 06:17:51.166294 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling MajorDeltaCompactionOp(b7ac1ab8d9b242d7841094a3494ba03c): perf score=1.000000
I20260812 06:17:51.285705 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: MajorDeltaCompactionOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.119s	user 0.079s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1022,"lbm_read_time_us":8673,"lbm_reads_lt_1ms":464,"lbm_write_time_us":22541,"lbm_writes_lt_1ms":443,"mutex_wait_us":327,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:17:51.286154 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c): perf score=11.118625
I20260812 06:17:51.318868 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.033s	user 0.021s	sys 0.008s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":13456,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:51.319345 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c): perf score=2.188937
I20260812 06:17:51.342267 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.023s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5104,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:51.342726 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c): perf score=2.188937
I20260812 06:17:51.352169 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.009s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3659,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:51.352569 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling MajorDeltaCompactionOp(b7ac1ab8d9b242d7841094a3494ba03c): perf score=1.000000
I20260812 06:17:51.489856 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: MajorDeltaCompactionOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.137s	user 0.109s	sys 0.028s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":317,"lbm_read_time_us":9684,"lbm_reads_lt_1ms":573,"lbm_write_time_us":27396,"lbm_writes_lt_1ms":543,"mutex_wait_us":55,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9856,"update_count":2500}
I20260812 06:17:51.490335 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c): perf score=11.118625
I20260812 06:17:51.529547 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.039s	user 0.029s	sys 0.007s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":16714,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:51.530085 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c): perf score=2.188937
I20260812 06:17:51.538888 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.009s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3247,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:51.539266 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling MajorDeltaCompactionOp(b7ac1ab8d9b242d7841094a3494ba03c): perf score=1.000000
I20260812 06:17:51.660530 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: MajorDeltaCompactionOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.121s	user 0.101s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672269,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":560,"lbm_read_time_us":7512,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23899,"lbm_writes_lt_1ms":443,"mutex_wait_us":38,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5632,"update_count":2000}
I20260812 06:17:51.663257 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c): perf score=10.126437
I20260812 06:17:51.705960 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.043s	user 0.023s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14071,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:51.706470 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c): perf score=2.188937
I20260812 06:17:51.716317 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3738,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:51.716724 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling FlushMRSOp(b7ac1ab8d9b242d7841094a3494ba03c): perf score=1.000000
I20260812 06:17:51.754181 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: FlushMRSOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.037s	user 0.021s	sys 0.004s Metrics: {"bytes_written":1152512,"cfile_init":1,"dirs.queue_time_us":48,"dirs.run_cpu_time_us":165,"dirs.run_wall_time_us":1248,"drs_written":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1380,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:51.754860 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling LogGCOp(b7ac1ab8d9b242d7841094a3494ba03c): free 112692556 bytes of WAL
I20260812 06:17:51.755064 20101 log_reader.cc:385] T b7ac1ab8d9b242d7841094a3494ba03c: removed 11 log segments from log reader
I20260812 06:17:51.755108 20101 log.cc:1079] T b7ac1ab8d9b242d7841094a3494ba03c P 4be7c193b4d24288a282ad958d6856f7: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/b7ac1ab8d9b242d7841094a3494ba03c/wal-000000028 (ops 135-139)
I20260812 06:17:51.755136 20101 log.cc:1079] T b7ac1ab8d9b242d7841094a3494ba03c P 4be7c193b4d24288a282ad958d6856f7: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/b7ac1ab8d9b242d7841094a3494ba03c/wal-000000029 (ops 140-144)
I20260812 06:17:51.755165 20101 log.cc:1079] T b7ac1ab8d9b242d7841094a3494ba03c P 4be7c193b4d24288a282ad958d6856f7: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/b7ac1ab8d9b242d7841094a3494ba03c/wal-000000030 (ops 145-149)
I20260812 06:17:51.755194 20101 log.cc:1079] T b7ac1ab8d9b242d7841094a3494ba03c P 4be7c193b4d24288a282ad958d6856f7: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/b7ac1ab8d9b242d7841094a3494ba03c/wal-000000031 (ops 150-154)
I20260812 06:17:51.755226 20101 log.cc:1079] T b7ac1ab8d9b242d7841094a3494ba03c P 4be7c193b4d24288a282ad958d6856f7: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/b7ac1ab8d9b242d7841094a3494ba03c/wal-000000032 (ops 155-159)
I20260812 06:17:51.755259 20101 log.cc:1079] T b7ac1ab8d9b242d7841094a3494ba03c P 4be7c193b4d24288a282ad958d6856f7: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/b7ac1ab8d9b242d7841094a3494ba03c/wal-000000033 (ops 160-164)
I20260812 06:17:51.755306 20101 log.cc:1079] T b7ac1ab8d9b242d7841094a3494ba03c P 4be7c193b4d24288a282ad958d6856f7: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/b7ac1ab8d9b242d7841094a3494ba03c/wal-000000034 (ops 165-169)
I20260812 06:17:51.755330 20101 log.cc:1079] T b7ac1ab8d9b242d7841094a3494ba03c P 4be7c193b4d24288a282ad958d6856f7: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/b7ac1ab8d9b242d7841094a3494ba03c/wal-000000035 (ops 170-174)
I20260812 06:17:51.755362 20101 log.cc:1079] T b7ac1ab8d9b242d7841094a3494ba03c P 4be7c193b4d24288a282ad958d6856f7: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/b7ac1ab8d9b242d7841094a3494ba03c/wal-000000036 (ops 175-179)
I20260812 06:17:51.755394 20101 log.cc:1079] T b7ac1ab8d9b242d7841094a3494ba03c P 4be7c193b4d24288a282ad958d6856f7: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/b7ac1ab8d9b242d7841094a3494ba03c/wal-000000037 (ops 180-184)
I20260812 06:17:51.755427 20101 log.cc:1079] T b7ac1ab8d9b242d7841094a3494ba03c P 4be7c193b4d24288a282ad958d6856f7: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/b7ac1ab8d9b242d7841094a3494ba03c/wal-000000038 (ops 185-189)
I20260812 06:17:51.776472 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: LogGCOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.021s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:17:51.776842 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling UndoDeltaBlockGCOp(b7ac1ab8d9b242d7841094a3494ba03c): 447 bytes on disk
I20260812 06:17:51.777240 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: UndoDeltaBlockGCOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4}
I20260812 06:17:51.777761 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c): perf score=2.188937
I20260812 06:17:51.797706 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.020s	user 0.003s	sys 0.010s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5817,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:51.798156 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c): perf score=2.188937
I20260812 06:17:51.807832 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3660,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:51.808388 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling MajorDeltaCompactionOp(b7ac1ab8d9b242d7841094a3494ba03c): perf score=1.000000
I20260812 06:17:51.972424 19929 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.608s	user 1.669s	sys 0.115s
I20260812 06:17:51.982306 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: MajorDeltaCompactionOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.174s	user 0.108s	sys 0.065s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877339,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":134,"lbm_read_time_us":12888,"lbm_reads_lt_1ms":674,"lbm_write_time_us":27072,"lbm_writes_lt_1ms":643,"mutex_wait_us":34,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":31488,"thread_start_us":72,"threads_started":1,"update_count":3000}
I20260812 06:17:51.983457 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c): perf score=14.095187
I20260812 06:17:52.027980 19929 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.055s	user 0.006s	sys 0.000s
I20260812 06:17:52.028820 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: FlushDeltaMemStoresOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.045s	user 0.033s	sys 0.011s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":19740,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:52.029270 19929 tablet_server.cc:179] TabletServer@127.19.118.65:0 shutting down...
I20260812 06:17:52.029378 20200 maintenance_manager.cc:419] P 4be7c193b4d24288a282ad958d6856f7: Scheduling MajorDeltaCompactionOp(b7ac1ab8d9b242d7841094a3494ba03c): perf score=1.000000
I20260812 06:17:52.140266 20101 maintenance_manager.cc:643] P 4be7c193b4d24288a282ad958d6856f7: MajorDeltaCompactionOp(b7ac1ab8d9b242d7841094a3494ba03c) complete. Timing: real 0.111s	user 0.086s	sys 0.024s Metrics: {"cfile_cache_hit":30,"cfile_cache_hit_bytes":4262390,"cfile_cache_miss":401,"cfile_cache_miss_bytes":16409766,"cfile_init":3,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":350,"lbm_read_time_us":6014,"lbm_reads_lt_1ms":413,"lbm_write_time_us":18628,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4352,"update_count":2000}
I20260812 06:17:52.140945 19929 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:52.141592 19929 tablet_replica.cc:333] T b7ac1ab8d9b242d7841094a3494ba03c P 4be7c193b4d24288a282ad958d6856f7: stopping tablet replica
I20260812 06:17:52.141829 19929 raft_consensus.cc:2243] T b7ac1ab8d9b242d7841094a3494ba03c P 4be7c193b4d24288a282ad958d6856f7 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:52.142051 19929 raft_consensus.cc:2272] T b7ac1ab8d9b242d7841094a3494ba03c P 4be7c193b4d24288a282ad958d6856f7 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:52.157102 19929 tablet_server.cc:196] TabletServer@127.19.118.65:0 shutdown complete.
I20260812 06:17:52.178918 19929 master.cc:562] Master@127.19.118.126:46589 shutting down...
I20260812 06:17:52.182422 19929 raft_consensus.cc:2243] T 00000000000000000000000000000000 P a94be9e0924542ac9021974cd76b2ce1 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:52.182579 19929 raft_consensus.cc:2272] T 00000000000000000000000000000000 P a94be9e0924542ac9021974cd76b2ce1 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:52.182651 19929 tablet_replica.cc:333] T 00000000000000000000000000000000 P a94be9e0924542ac9021974cd76b2ce1: stopping tablet replica
I20260812 06:17:52.194708 19929 master.cc:584] Master@127.19.118.126:46589 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5205 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:17:52.269488 19929 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.19.118.126:37143
I20260812 06:17:52.269819 19929 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:52.271668 20261 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:17:52.271749 20259 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:17:52.271793 19929 server_base.cc:1061] running on GCE node
W20260812 06:17:52.271875 20265 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:17:52.272069 19929 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:52.272111 19929 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:17:52.272125 19929 hybrid_clock.cc:648] HybridClock initialized: now 1786515472272125 us; error 0 us; skew 500 ppm
I20260812 06:17:52.272876 19929 webserver.cc:533] Webserver started at http://127.19.118.126:42685/ using document root <none> and password file <none>
I20260812 06:17:52.273020 19929 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:52.273065 19929 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:52.273137 19929 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:52.273494 19929 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515467054230-19929-0/minicluster-data/master-0-root/instance:
uuid: "8630735969684cbcb4b36984360b02be"
format_stamp: "Formatted at 2026-08-12 06:17:52 on dist-test-slave-1l3l"
I20260812 06:17:52.274915 19929 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:52.275799 20274 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:17:52.276024 19929 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:52.276089 19929 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515467054230-19929-0/minicluster-data/master-0-root
uuid: "8630735969684cbcb4b36984360b02be"
format_stamp: "Formatted at 2026-08-12 06:17:52 on dist-test-slave-1l3l"
I20260812 06:17:52.276155 19929 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515467054230-19929-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515467054230-19929-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515467054230-19929-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:17:52.293398 19929 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:52.293745 19929 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:52.297668 19929 rpc_server.cc:307] RPC server started. Bound to: 127.19.118.126:37143
I20260812 06:17:52.313032 20369 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.19.118.126:37143 every 8 connection(s)
I20260812 06:17:52.313498 20372 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:17:52.315203 20372 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 8630735969684cbcb4b36984360b02be: Bootstrap starting.
I20260812 06:17:52.315968 20372 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 8630735969684cbcb4b36984360b02be: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:52.316870 20372 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 8630735969684cbcb4b36984360b02be: No bootstrap required, opened a new log
I20260812 06:17:52.317216 20372 raft_consensus.cc:359] T 00000000000000000000000000000000 P 8630735969684cbcb4b36984360b02be [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8630735969684cbcb4b36984360b02be" member_type: VOTER }
I20260812 06:17:52.317296 20372 raft_consensus.cc:385] T 00000000000000000000000000000000 P 8630735969684cbcb4b36984360b02be [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:52.317323 20372 raft_consensus.cc:740] T 00000000000000000000000000000000 P 8630735969684cbcb4b36984360b02be [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 8630735969684cbcb4b36984360b02be, State: Initialized, Role: FOLLOWER
I20260812 06:17:52.317430 20372 consensus_queue.cc:260] T 00000000000000000000000000000000 P 8630735969684cbcb4b36984360b02be [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: "8630735969684cbcb4b36984360b02be" member_type: VOTER }
I20260812 06:17:52.317488 20372 raft_consensus.cc:399] T 00000000000000000000000000000000 P 8630735969684cbcb4b36984360b02be [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:52.317514 20372 raft_consensus.cc:493] T 00000000000000000000000000000000 P 8630735969684cbcb4b36984360b02be [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:52.317546 20372 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 8630735969684cbcb4b36984360b02be [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:52.318172 20372 raft_consensus.cc:515] T 00000000000000000000000000000000 P 8630735969684cbcb4b36984360b02be [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8630735969684cbcb4b36984360b02be" member_type: VOTER }
I20260812 06:17:52.318285 20372 leader_election.cc:304] T 00000000000000000000000000000000 P 8630735969684cbcb4b36984360b02be [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: 8630735969684cbcb4b36984360b02be; no voters: 
I20260812 06:17:52.318428 20372 leader_election.cc:290] T 00000000000000000000000000000000 P 8630735969684cbcb4b36984360b02be [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:52.318518 20375 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 8630735969684cbcb4b36984360b02be [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:52.318693 20375 raft_consensus.cc:697] T 00000000000000000000000000000000 P 8630735969684cbcb4b36984360b02be [term 1 LEADER]: Becoming Leader. State: Replica: 8630735969684cbcb4b36984360b02be, State: Running, Role: LEADER
I20260812 06:17:52.318835 20372 sys_catalog.cc:565] T 00000000000000000000000000000000 P 8630735969684cbcb4b36984360b02be [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:52.318816 20375 consensus_queue.cc:237] T 00000000000000000000000000000000 P 8630735969684cbcb4b36984360b02be [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: "8630735969684cbcb4b36984360b02be" member_type: VOTER }
I20260812 06:17:52.319231 20377 sys_catalog.cc:455] T 00000000000000000000000000000000 P 8630735969684cbcb4b36984360b02be [sys.catalog]: SysCatalogTable state changed. Reason: New leader 8630735969684cbcb4b36984360b02be. Latest consensus state: current_term: 1 leader_uuid: "8630735969684cbcb4b36984360b02be" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8630735969684cbcb4b36984360b02be" member_type: VOTER } }
I20260812 06:17:52.319217 20376 sys_catalog.cc:455] T 00000000000000000000000000000000 P 8630735969684cbcb4b36984360b02be [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "8630735969684cbcb4b36984360b02be" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8630735969684cbcb4b36984360b02be" member_type: VOTER } }
I20260812 06:17:52.319330 20376 sys_catalog.cc:458] T 00000000000000000000000000000000 P 8630735969684cbcb4b36984360b02be [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:52.319321 20377 sys_catalog.cc:458] T 00000000000000000000000000000000 P 8630735969684cbcb4b36984360b02be [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:52.319954 20382 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:52.320820 20382 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:52.321045 19929 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:52.322467 20382 catalog_manager.cc:1383] Generated new cluster ID: 21a8d7f248894847a96ddfdf617f5014
I20260812 06:17:52.322513 20382 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:52.331611 20382 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:52.332247 20382 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:52.340018 20382 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 8630735969684cbcb4b36984360b02be: Generated new TSK 0
I20260812 06:17:52.340164 20382 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:52.353142 19929 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:52.354938 20409 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:17:52.355022 20413 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:17:52.355105 19929 server_base.cc:1061] running on GCE node
W20260812 06:17:52.355154 20410 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:17:52.355332 19929 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:52.355374 19929 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:17:52.355391 19929 hybrid_clock.cc:648] HybridClock initialized: now 1786515472355390 us; error 0 us; skew 500 ppm
I20260812 06:17:52.356177 19929 webserver.cc:533] Webserver started at http://127.19.118.65:39417/ using document root <none> and password file <none>
I20260812 06:17:52.356320 19929 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:52.356366 19929 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:52.356437 19929 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:52.356789 19929 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515467054230-19929-0/minicluster-data/ts-0-root/instance:
uuid: "27f5ebddcd1248449a847a09b52c3c07"
format_stamp: "Formatted at 2026-08-12 06:17:52 on dist-test-slave-1l3l"
I20260812 06:17:52.358151 19929 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:52.358955 20418 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:17:52.359155 19929 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:52.359216 19929 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515467054230-19929-0/minicluster-data/ts-0-root
uuid: "27f5ebddcd1248449a847a09b52c3c07"
format_stamp: "Formatted at 2026-08-12 06:17:52 on dist-test-slave-1l3l"
I20260812 06:17:52.359282 19929 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515467054230-19929-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515467054230-19929-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515467054230-19929-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:17:52.373742 19929 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:52.374050 19929 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:52.374300 19929 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:52.374722 19929 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:52.374758 19929 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:52.374799 19929 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:52.374826 19929 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:52.378710 19929 rpc_server.cc:307] RPC server started. Bound to: 127.19.118.65:33795
I20260812 06:17:52.378736 20535 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.19.118.65:33795 every 8 connection(s)
I20260812 06:17:52.386883 20536 heartbeater.cc:344] Connected to a master server at 127.19.118.126:37143
I20260812 06:17:52.386972 20536 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:52.387190 20536 heartbeater.cc:507] Master 127.19.118.126:37143 requested a full tablet report, sending...
I20260812 06:17:52.387890 20314 ts_manager.cc:194] Registered new tserver with Master: 27f5ebddcd1248449a847a09b52c3c07 (127.19.118.65:33795)
I20260812 06:17:52.387949 19929 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.00886032s
I20260812 06:17:52.388638 20314 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:45616
I20260812 06:17:52.394335 20314 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:45624:
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:17:52.402376 20475 tablet_service.cc:1511] Processing CreateTablet for tablet 1cb921a51aa142dab23389ba4cba75c7 (DEFAULT_TABLE table=heavy-update-compaction-test [id=0286efd95183401e9188c914ebba993c]), partition=
I20260812 06:17:52.402616 20475 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 1cb921a51aa142dab23389ba4cba75c7. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:52.404476 20553 tablet_bootstrap.cc:492] T 1cb921a51aa142dab23389ba4cba75c7 P 27f5ebddcd1248449a847a09b52c3c07: Bootstrap starting.
I20260812 06:17:52.405409 20553 tablet_bootstrap.cc:654] T 1cb921a51aa142dab23389ba4cba75c7 P 27f5ebddcd1248449a847a09b52c3c07: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:52.406340 20553 tablet_bootstrap.cc:492] T 1cb921a51aa142dab23389ba4cba75c7 P 27f5ebddcd1248449a847a09b52c3c07: No bootstrap required, opened a new log
I20260812 06:17:52.406410 20553 ts_tablet_manager.cc:1403] T 1cb921a51aa142dab23389ba4cba75c7 P 27f5ebddcd1248449a847a09b52c3c07: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:17:52.406765 20553 raft_consensus.cc:359] T 1cb921a51aa142dab23389ba4cba75c7 P 27f5ebddcd1248449a847a09b52c3c07 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "27f5ebddcd1248449a847a09b52c3c07" member_type: VOTER last_known_addr { host: "127.19.118.65" port: 33795 } }
I20260812 06:17:52.406847 20553 raft_consensus.cc:385] T 1cb921a51aa142dab23389ba4cba75c7 P 27f5ebddcd1248449a847a09b52c3c07 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:52.406873 20553 raft_consensus.cc:740] T 1cb921a51aa142dab23389ba4cba75c7 P 27f5ebddcd1248449a847a09b52c3c07 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 27f5ebddcd1248449a847a09b52c3c07, State: Initialized, Role: FOLLOWER
I20260812 06:17:52.406962 20553 consensus_queue.cc:260] T 1cb921a51aa142dab23389ba4cba75c7 P 27f5ebddcd1248449a847a09b52c3c07 [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: "27f5ebddcd1248449a847a09b52c3c07" member_type: VOTER last_known_addr { host: "127.19.118.65" port: 33795 } }
I20260812 06:17:52.407022 20553 raft_consensus.cc:399] T 1cb921a51aa142dab23389ba4cba75c7 P 27f5ebddcd1248449a847a09b52c3c07 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:52.407048 20553 raft_consensus.cc:493] T 1cb921a51aa142dab23389ba4cba75c7 P 27f5ebddcd1248449a847a09b52c3c07 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:52.407080 20553 raft_consensus.cc:3060] T 1cb921a51aa142dab23389ba4cba75c7 P 27f5ebddcd1248449a847a09b52c3c07 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:52.407789 20553 raft_consensus.cc:515] T 1cb921a51aa142dab23389ba4cba75c7 P 27f5ebddcd1248449a847a09b52c3c07 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "27f5ebddcd1248449a847a09b52c3c07" member_type: VOTER last_known_addr { host: "127.19.118.65" port: 33795 } }
I20260812 06:17:52.407932 20553 leader_election.cc:304] T 1cb921a51aa142dab23389ba4cba75c7 P 27f5ebddcd1248449a847a09b52c3c07 [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: 27f5ebddcd1248449a847a09b52c3c07; no voters: 
I20260812 06:17:52.408118 20553 leader_election.cc:290] T 1cb921a51aa142dab23389ba4cba75c7 P 27f5ebddcd1248449a847a09b52c3c07 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:52.408227 20556 raft_consensus.cc:2804] T 1cb921a51aa142dab23389ba4cba75c7 P 27f5ebddcd1248449a847a09b52c3c07 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:52.408460 20556 raft_consensus.cc:697] T 1cb921a51aa142dab23389ba4cba75c7 P 27f5ebddcd1248449a847a09b52c3c07 [term 1 LEADER]: Becoming Leader. State: Replica: 27f5ebddcd1248449a847a09b52c3c07, State: Running, Role: LEADER
I20260812 06:17:52.408463 20553 ts_tablet_manager.cc:1434] T 1cb921a51aa142dab23389ba4cba75c7 P 27f5ebddcd1248449a847a09b52c3c07: Time spent starting tablet: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:17:52.408605 20556 consensus_queue.cc:237] T 1cb921a51aa142dab23389ba4cba75c7 P 27f5ebddcd1248449a847a09b52c3c07 [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: "27f5ebddcd1248449a847a09b52c3c07" member_type: VOTER last_known_addr { host: "127.19.118.65" port: 33795 } }
I20260812 06:17:52.408650 20536 heartbeater.cc:499] Master 127.19.118.126:37143 was elected leader, sending a full tablet report...
I20260812 06:17:52.409911 20314 catalog_manager.cc:5719] T 1cb921a51aa142dab23389ba4cba75c7 P 27f5ebddcd1248449a847a09b52c3c07 reported cstate change: term changed from 0 to 1, leader changed from <none> to 27f5ebddcd1248449a847a09b52c3c07 (127.19.118.65). New cstate: current_term: 1 leader_uuid: "27f5ebddcd1248449a847a09b52c3c07" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "27f5ebddcd1248449a847a09b52c3c07" member_type: VOTER last_known_addr { host: "127.19.118.65" port: 33795 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:52.463675 19929 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.050s	user 0.016s	sys 0.006s
I20260812 06:17:52.629608 20539 maintenance_manager.cc:419] P 27f5ebddcd1248449a847a09b52c3c07: Scheduling FlushMRSOp(1cb921a51aa142dab23389ba4cba75c7): perf score=23.023690
I20260812 06:17:52.790303 20431 maintenance_manager.cc:643] P 27f5ebddcd1248449a847a09b52c3c07: FlushMRSOp(1cb921a51aa142dab23389ba4cba75c7) complete. Timing: real 0.160s	user 0.113s	sys 0.044s Metrics: {"bytes_written":12717735,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":465,"dirs.run_cpu_time_us":209,"dirs.run_wall_time_us":823,"drs_written":1,"lbm_read_time_us":74,"lbm_reads_lt_1ms":4,"lbm_write_time_us":40265,"lbm_writes_lt_1ms":867,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"update_count":1550}
I20260812 06:17:52.790990 20539 maintenance_manager.cc:419] P 27f5ebddcd1248449a847a09b52c3c07: Scheduling LogGCOp(1cb921a51aa142dab23389ba4cba75c7): free 20743880 bytes of WAL
I20260812 06:17:52.791263 20431 log_reader.cc:385] T 1cb921a51aa142dab23389ba4cba75c7: removed 2 log segments from log reader
I20260812 06:17:52.791314 20431 log.cc:1079] T 1cb921a51aa142dab23389ba4cba75c7 P 27f5ebddcd1248449a847a09b52c3c07: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/1cb921a51aa142dab23389ba4cba75c7/wal-000000001 (ops 1-6)
I20260812 06:17:52.791354 20431 log.cc:1079] T 1cb921a51aa142dab23389ba4cba75c7 P 27f5ebddcd1248449a847a09b52c3c07: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/1cb921a51aa142dab23389ba4cba75c7/wal-000000002 (ops 7-11)
I20260812 06:17:52.795122 20431 maintenance_manager.cc:643] P 27f5ebddcd1248449a847a09b52c3c07: LogGCOp(1cb921a51aa142dab23389ba4cba75c7) complete. Timing: real 0.004s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:17:52.795473 20539 maintenance_manager.cc:419] P 27f5ebddcd1248449a847a09b52c3c07: Scheduling FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7): perf score=2.188937
I20260812 06:17:52.806095 20431 maintenance_manager.cc:643] P 27f5ebddcd1248449a847a09b52c3c07: FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3558,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:52.806509 20539 maintenance_manager.cc:419] P 27f5ebddcd1248449a847a09b52c3c07: Scheduling FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7): perf score=2.188937
I20260812 06:17:52.815410 20431 maintenance_manager.cc:643] P 27f5ebddcd1248449a847a09b52c3c07: FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7) complete. Timing: real 0.009s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3273,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:52.815932 20539 maintenance_manager.cc:419] P 27f5ebddcd1248449a847a09b52c3c07: Scheduling UndoDeltaBlockGCOp(1cb921a51aa142dab23389ba4cba75c7): 20513816 bytes on disk
I20260812 06:17:52.816362 20431 maintenance_manager.cc:643] P 27f5ebddcd1248449a847a09b52c3c07: UndoDeltaBlockGCOp(1cb921a51aa142dab23389ba4cba75c7) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4}
I20260812 06:17:52.816746 20539 maintenance_manager.cc:419] P 27f5ebddcd1248449a847a09b52c3c07: Scheduling MajorDeltaCompactionOp(1cb921a51aa142dab23389ba4cba75c7): perf score=1.000000
I20260812 06:17:52.986994 20431 maintenance_manager.cc:643] P 27f5ebddcd1248449a847a09b52c3c07: MajorDeltaCompactionOp(1cb921a51aa142dab23389ba4cba75c7) complete. Timing: real 0.170s	user 0.101s	sys 0.056s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815794,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":430,"lbm_read_time_us":13055,"lbm_reads_lt_1ms":569,"lbm_write_time_us":27288,"lbm_writes_lt_1ms":543,"mutex_wait_us":48,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1792,"thread_start_us":321,"threads_started":5,"update_count":2500}
I20260812 06:17:52.987461 20539 maintenance_manager.cc:419] P 27f5ebddcd1248449a847a09b52c3c07: Scheduling FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7): perf score=14.095187
I20260812 06:17:53.034447 20431 maintenance_manager.cc:643] P 27f5ebddcd1248449a847a09b52c3c07: FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7) complete. Timing: real 0.047s	user 0.019s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":16256,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:53.034926 20539 maintenance_manager.cc:419] P 27f5ebddcd1248449a847a09b52c3c07: Scheduling FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7): perf score=2.188937
I20260812 06:17:53.045091 20431 maintenance_manager.cc:643] P 27f5ebddcd1248449a847a09b52c3c07: FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7) complete. Timing: real 0.010s	user 0.008s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3630,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:53.045717 20539 maintenance_manager.cc:419] P 27f5ebddcd1248449a847a09b52c3c07: Scheduling MajorDeltaCompactionOp(1cb921a51aa142dab23389ba4cba75c7): perf score=1.000000
I20260812 06:17:53.201184 20431 maintenance_manager.cc:643] P 27f5ebddcd1248449a847a09b52c3c07: MajorDeltaCompactionOp(1cb921a51aa142dab23389ba4cba75c7) complete. Timing: real 0.155s	user 0.100s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":137,"lbm_read_time_us":9308,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29801,"lbm_writes_lt_1ms":543,"mutex_wait_us":55,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:17:53.201709 20539 maintenance_manager.cc:419] P 27f5ebddcd1248449a847a09b52c3c07: Scheduling FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7): perf score=14.095187
I20260812 06:17:53.252650 20431 maintenance_manager.cc:643] P 27f5ebddcd1248449a847a09b52c3c07: FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7) complete. Timing: real 0.051s	user 0.026s	sys 0.023s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21306,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:53.253178 20539 maintenance_manager.cc:419] P 27f5ebddcd1248449a847a09b52c3c07: Scheduling FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7): perf score=2.188937
I20260812 06:17:53.264199 20431 maintenance_manager.cc:643] P 27f5ebddcd1248449a847a09b52c3c07: FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4074,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:53.264657 20539 maintenance_manager.cc:419] P 27f5ebddcd1248449a847a09b52c3c07: Scheduling MajorDeltaCompactionOp(1cb921a51aa142dab23389ba4cba75c7): perf score=1.000000
I20260812 06:17:53.405462 20431 maintenance_manager.cc:643] P 27f5ebddcd1248449a847a09b52c3c07: MajorDeltaCompactionOp(1cb921a51aa142dab23389ba4cba75c7) complete. Timing: real 0.141s	user 0.110s	sys 0.027s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":815,"lbm_read_time_us":9759,"lbm_reads_lt_1ms":564,"lbm_write_time_us":27111,"lbm_writes_lt_1ms":543,"mutex_wait_us":316,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":2500}
I20260812 06:17:53.405995 20539 maintenance_manager.cc:419] P 27f5ebddcd1248449a847a09b52c3c07: Scheduling FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7): perf score=11.118625
I20260812 06:17:53.442510 20431 maintenance_manager.cc:643] P 27f5ebddcd1248449a847a09b52c3c07: FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7) complete. Timing: real 0.036s	user 0.020s	sys 0.014s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15568,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"spinlock_wait_cycles":8448,"update_count":1550}
I20260812 06:17:53.443233 20539 maintenance_manager.cc:419] P 27f5ebddcd1248449a847a09b52c3c07: Scheduling FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7): perf score=2.188937
I20260812 06:17:53.457785 20431 maintenance_manager.cc:643] P 27f5ebddcd1248449a847a09b52c3c07: FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7) complete. Timing: real 0.014s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4296,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:53.458292 20539 maintenance_manager.cc:419] P 27f5ebddcd1248449a847a09b52c3c07: Scheduling FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7): perf score=2.188937
I20260812 06:17:53.467801 20431 maintenance_manager.cc:643] P 27f5ebddcd1248449a847a09b52c3c07: FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7) complete. Timing: real 0.009s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3596,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:53.468269 20539 maintenance_manager.cc:419] P 27f5ebddcd1248449a847a09b52c3c07: Scheduling MajorDeltaCompactionOp(1cb921a51aa142dab23389ba4cba75c7): perf score=1.000000
I20260812 06:17:53.630143 20431 maintenance_manager.cc:643] P 27f5ebddcd1248449a847a09b52c3c07: MajorDeltaCompactionOp(1cb921a51aa142dab23389ba4cba75c7) complete. Timing: real 0.162s	user 0.102s	sys 0.040s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815793,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1024,"lbm_read_time_us":9767,"lbm_reads_lt_1ms":573,"lbm_write_time_us":28751,"lbm_writes_lt_1ms":543,"mutex_wait_us":386,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":21632,"update_count":2500}
I20260812 06:17:53.630939 20539 maintenance_manager.cc:419] P 27f5ebddcd1248449a847a09b52c3c07: Scheduling FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7): perf score=14.095187
I20260812 06:17:53.686524 20431 maintenance_manager.cc:643] P 27f5ebddcd1248449a847a09b52c3c07: FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7) complete. Timing: real 0.055s	user 0.019s	sys 0.019s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":18407,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:53.687219 20539 maintenance_manager.cc:419] P 27f5ebddcd1248449a847a09b52c3c07: Scheduling FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7): perf score=2.188937
I20260812 06:17:53.699653 20431 maintenance_manager.cc:643] P 27f5ebddcd1248449a847a09b52c3c07: FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7) complete. Timing: real 0.012s	user 0.009s	sys 0.000s 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:17:53.700461 20539 maintenance_manager.cc:419] P 27f5ebddcd1248449a847a09b52c3c07: Scheduling MajorDeltaCompactionOp(1cb921a51aa142dab23389ba4cba75c7): perf score=1.000000
I20260812 06:17:53.879163 20431 maintenance_manager.cc:643] P 27f5ebddcd1248449a847a09b52c3c07: MajorDeltaCompactionOp(1cb921a51aa142dab23389ba4cba75c7) complete. Timing: real 0.179s	user 0.133s	sys 0.045s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":319,"lbm_read_time_us":12001,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27404,"lbm_writes_lt_1ms":543,"mutex_wait_us":56,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":80256,"update_count":2500}
I20260812 06:17:53.879843 20539 maintenance_manager.cc:419] P 27f5ebddcd1248449a847a09b52c3c07: Scheduling FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7): perf score=14.095187
I20260812 06:17:53.929293 20431 maintenance_manager.cc:643] P 27f5ebddcd1248449a847a09b52c3c07: FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7) complete. Timing: real 0.049s	user 0.027s	sys 0.021s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22438,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:53.929813 20539 maintenance_manager.cc:419] P 27f5ebddcd1248449a847a09b52c3c07: Scheduling FlushMRSOp(1cb921a51aa142dab23389ba4cba75c7): perf score=1.000000
I20260812 06:17:53.956156 20431 maintenance_manager.cc:643] P 27f5ebddcd1248449a847a09b52c3c07: FlushMRSOp(1cb921a51aa142dab23389ba4cba75c7) complete. Timing: real 0.026s	user 0.026s	sys 0.000s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":65,"dirs.run_cpu_time_us":220,"dirs.run_wall_time_us":1280,"drs_written":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1761,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:17:53.956825 20539 maintenance_manager.cc:419] P 27f5ebddcd1248449a847a09b52c3c07: Scheduling LogGCOp(1cb921a51aa142dab23389ba4cba75c7): free 124710287 bytes of WAL
I20260812 06:17:53.957093 20431 log_reader.cc:385] T 1cb921a51aa142dab23389ba4cba75c7: removed 12 log segments from log reader
I20260812 06:17:53.957155 20431 log.cc:1079] T 1cb921a51aa142dab23389ba4cba75c7 P 27f5ebddcd1248449a847a09b52c3c07: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/1cb921a51aa142dab23389ba4cba75c7/wal-000000003 (ops 12-16)
I20260812 06:17:53.957197 20431 log.cc:1079] T 1cb921a51aa142dab23389ba4cba75c7 P 27f5ebddcd1248449a847a09b52c3c07: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/1cb921a51aa142dab23389ba4cba75c7/wal-000000004 (ops 17-21)
I20260812 06:17:53.957221 20431 log.cc:1079] T 1cb921a51aa142dab23389ba4cba75c7 P 27f5ebddcd1248449a847a09b52c3c07: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/1cb921a51aa142dab23389ba4cba75c7/wal-000000005 (ops 22-26)
I20260812 06:17:53.957250 20431 log.cc:1079] T 1cb921a51aa142dab23389ba4cba75c7 P 27f5ebddcd1248449a847a09b52c3c07: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/1cb921a51aa142dab23389ba4cba75c7/wal-000000006 (ops 27-31)
I20260812 06:17:53.957280 20431 log.cc:1079] T 1cb921a51aa142dab23389ba4cba75c7 P 27f5ebddcd1248449a847a09b52c3c07: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/1cb921a51aa142dab23389ba4cba75c7/wal-000000007 (ops 32-36)
I20260812 06:17:53.957314 20431 log.cc:1079] T 1cb921a51aa142dab23389ba4cba75c7 P 27f5ebddcd1248449a847a09b52c3c07: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/1cb921a51aa142dab23389ba4cba75c7/wal-000000008 (ops 37-41)
I20260812 06:17:53.957341 20431 log.cc:1079] T 1cb921a51aa142dab23389ba4cba75c7 P 27f5ebddcd1248449a847a09b52c3c07: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/1cb921a51aa142dab23389ba4cba75c7/wal-000000009 (ops 42-46)
I20260812 06:17:53.957369 20431 log.cc:1079] T 1cb921a51aa142dab23389ba4cba75c7 P 27f5ebddcd1248449a847a09b52c3c07: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/1cb921a51aa142dab23389ba4cba75c7/wal-000000010 (ops 47-51)
I20260812 06:17:53.957398 20431 log.cc:1079] T 1cb921a51aa142dab23389ba4cba75c7 P 27f5ebddcd1248449a847a09b52c3c07: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/1cb921a51aa142dab23389ba4cba75c7/wal-000000011 (ops 52-56)
I20260812 06:17:53.957427 20431 log.cc:1079] T 1cb921a51aa142dab23389ba4cba75c7 P 27f5ebddcd1248449a847a09b52c3c07: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/1cb921a51aa142dab23389ba4cba75c7/wal-000000012 (ops 57-61)
I20260812 06:17:53.957460 20431 log.cc:1079] T 1cb921a51aa142dab23389ba4cba75c7 P 27f5ebddcd1248449a847a09b52c3c07: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/1cb921a51aa142dab23389ba4cba75c7/wal-000000013 (ops 62-66)
I20260812 06:17:53.957484 20431 log.cc:1079] T 1cb921a51aa142dab23389ba4cba75c7 P 27f5ebddcd1248449a847a09b52c3c07: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/1cb921a51aa142dab23389ba4cba75c7/wal-000000014 (ops 67-71)
I20260812 06:17:53.984710 20431 maintenance_manager.cc:643] P 27f5ebddcd1248449a847a09b52c3c07: LogGCOp(1cb921a51aa142dab23389ba4cba75c7) complete. Timing: real 0.028s	user 0.004s	sys 0.023s Metrics: {}
I20260812 06:17:53.985117 20539 maintenance_manager.cc:419] P 27f5ebddcd1248449a847a09b52c3c07: Scheduling FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7): perf score=3.181125
I20260812 06:17:53.998796 20431 maintenance_manager.cc:643] P 27f5ebddcd1248449a847a09b52c3c07: FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7) complete. Timing: real 0.014s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4057,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:53.999229 20539 maintenance_manager.cc:419] P 27f5ebddcd1248449a847a09b52c3c07: Scheduling FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7): perf score=2.188937
I20260812 06:17:54.008916 20431 maintenance_manager.cc:643] P 27f5ebddcd1248449a847a09b52c3c07: FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3347,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:54.009404 20539 maintenance_manager.cc:419] P 27f5ebddcd1248449a847a09b52c3c07: Scheduling MajorDeltaCompactionOp(1cb921a51aa142dab23389ba4cba75c7): perf score=1.000000
I20260812 06:17:54.201020 20431 maintenance_manager.cc:643] P 27f5ebddcd1248449a847a09b52c3c07: MajorDeltaCompactionOp(1cb921a51aa142dab23389ba4cba75c7) complete. Timing: real 0.191s	user 0.116s	sys 0.075s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918205,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":819,"lbm_read_time_us":12881,"lbm_reads_lt_1ms":673,"lbm_write_time_us":32280,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":5376,"thread_start_us":84,"threads_started":1,"update_count":3000}
I20260812 06:17:54.204033 20539 maintenance_manager.cc:419] P 27f5ebddcd1248449a847a09b52c3c07: Scheduling FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7): perf score=14.095187
I20260812 06:17:54.256434 20431 maintenance_manager.cc:643] P 27f5ebddcd1248449a847a09b52c3c07: FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7) complete. Timing: real 0.052s	user 0.028s	sys 0.016s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":20001,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:54.256923 20539 maintenance_manager.cc:419] P 27f5ebddcd1248449a847a09b52c3c07: Scheduling UndoDeltaBlockGCOp(1cb921a51aa142dab23389ba4cba75c7): 472 bytes on disk
I20260812 06:17:54.257285 20431 maintenance_manager.cc:643] P 27f5ebddcd1248449a847a09b52c3c07: UndoDeltaBlockGCOp(1cb921a51aa142dab23389ba4cba75c7) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4}
I20260812 06:17:54.257725 20539 maintenance_manager.cc:419] P 27f5ebddcd1248449a847a09b52c3c07: Scheduling FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7): perf score=2.188937
I20260812 06:17:54.268580 20431 maintenance_manager.cc:643] P 27f5ebddcd1248449a847a09b52c3c07: FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3718,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:54.269106 20539 maintenance_manager.cc:419] P 27f5ebddcd1248449a847a09b52c3c07: Scheduling MajorDeltaCompactionOp(1cb921a51aa142dab23389ba4cba75c7): perf score=1.000000
I20260812 06:17:54.440367 20431 maintenance_manager.cc:643] P 27f5ebddcd1248449a847a09b52c3c07: MajorDeltaCompactionOp(1cb921a51aa142dab23389ba4cba75c7) complete. Timing: real 0.171s	user 0.096s	sys 0.072s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":710,"lbm_read_time_us":11276,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29748,"lbm_writes_lt_1ms":543,"mutex_wait_us":2,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:17:54.440812 20539 maintenance_manager.cc:419] P 27f5ebddcd1248449a847a09b52c3c07: Scheduling FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7): perf score=14.095187
I20260812 06:17:54.494042 20431 maintenance_manager.cc:643] P 27f5ebddcd1248449a847a09b52c3c07: FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7) complete. Timing: real 0.053s	user 0.024s	sys 0.024s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":24411,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:17:54.494571 20539 maintenance_manager.cc:419] P 27f5ebddcd1248449a847a09b52c3c07: Scheduling FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7): perf score=2.188937
I20260812 06:17:54.505537 20431 maintenance_manager.cc:643] P 27f5ebddcd1248449a847a09b52c3c07: FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7) complete. Timing: real 0.011s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3823,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:54.506062 20539 maintenance_manager.cc:419] P 27f5ebddcd1248449a847a09b52c3c07: Scheduling MajorDeltaCompactionOp(1cb921a51aa142dab23389ba4cba75c7): perf score=1.000000
I20260812 06:17:54.668669 20431 maintenance_manager.cc:643] P 27f5ebddcd1248449a847a09b52c3c07: MajorDeltaCompactionOp(1cb921a51aa142dab23389ba4cba75c7) complete. Timing: real 0.162s	user 0.102s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":616,"lbm_read_time_us":11390,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25959,"lbm_writes_lt_1ms":543,"mutex_wait_us":41,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9856,"update_count":2500}
I20260812 06:17:54.669116 20539 maintenance_manager.cc:419] P 27f5ebddcd1248449a847a09b52c3c07: Scheduling FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7): perf score=14.095187
I20260812 06:17:54.723946 20431 maintenance_manager.cc:643] P 27f5ebddcd1248449a847a09b52c3c07: FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7) complete. Timing: real 0.055s	user 0.018s	sys 0.034s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":18476,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:54.724475 20539 maintenance_manager.cc:419] P 27f5ebddcd1248449a847a09b52c3c07: Scheduling FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7): perf score=2.188937
I20260812 06:17:54.738797 20431 maintenance_manager.cc:643] P 27f5ebddcd1248449a847a09b52c3c07: FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7) complete. Timing: real 0.014s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5607,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:54.739236 20539 maintenance_manager.cc:419] P 27f5ebddcd1248449a847a09b52c3c07: Scheduling MajorDeltaCompactionOp(1cb921a51aa142dab23389ba4cba75c7): perf score=1.000000
I20260812 06:17:54.904243 20431 maintenance_manager.cc:643] P 27f5ebddcd1248449a847a09b52c3c07: MajorDeltaCompactionOp(1cb921a51aa142dab23389ba4cba75c7) complete. Timing: real 0.165s	user 0.093s	sys 0.067s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":689,"lbm_read_time_us":11373,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26169,"lbm_writes_lt_1ms":543,"mutex_wait_us":46,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:17:54.904759 20539 maintenance_manager.cc:419] P 27f5ebddcd1248449a847a09b52c3c07: Scheduling FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7): perf score=11.118625
I20260812 06:17:54.950203 20431 maintenance_manager.cc:643] P 27f5ebddcd1248449a847a09b52c3c07: FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7) complete. Timing: real 0.045s	user 0.027s	sys 0.013s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":20110,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":311,"reinsert_count":0,"update_count":1550}
I20260812 06:17:54.950697 20539 maintenance_manager.cc:419] P 27f5ebddcd1248449a847a09b52c3c07: Scheduling FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7): perf score=2.188937
I20260812 06:17:54.970394 20431 maintenance_manager.cc:643] P 27f5ebddcd1248449a847a09b52c3c07: FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7) complete. Timing: real 0.020s	user 0.010s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3640,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:54.970857 20539 maintenance_manager.cc:419] P 27f5ebddcd1248449a847a09b52c3c07: Scheduling FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7): perf score=2.188937
I20260812 06:17:54.980325 20431 maintenance_manager.cc:643] P 27f5ebddcd1248449a847a09b52c3c07: FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7) complete. Timing: real 0.009s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3604,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:54.980754 20539 maintenance_manager.cc:419] P 27f5ebddcd1248449a847a09b52c3c07: Scheduling MajorDeltaCompactionOp(1cb921a51aa142dab23389ba4cba75c7): perf score=1.000000
I20260812 06:17:55.149616 20431 maintenance_manager.cc:643] P 27f5ebddcd1248449a847a09b52c3c07: MajorDeltaCompactionOp(1cb921a51aa142dab23389ba4cba75c7) complete. Timing: real 0.169s	user 0.100s	sys 0.068s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815794,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":88,"lbm_read_time_us":11538,"lbm_reads_lt_1ms":573,"lbm_write_time_us":27842,"lbm_writes_lt_1ms":543,"mutex_wait_us":19,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8448,"update_count":2500}
I20260812 06:17:55.150236 20539 maintenance_manager.cc:419] P 27f5ebddcd1248449a847a09b52c3c07: Scheduling FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7): perf score=11.118625
I20260812 06:17:55.183317 20431 maintenance_manager.cc:643] P 27f5ebddcd1248449a847a09b52c3c07: FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7) complete. Timing: real 0.033s	user 0.015s	sys 0.015s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14121,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:55.183914 20539 maintenance_manager.cc:419] P 27f5ebddcd1248449a847a09b52c3c07: Scheduling FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7): perf score=2.188937
I20260812 06:17:55.198017 20431 maintenance_manager.cc:643] P 27f5ebddcd1248449a847a09b52c3c07: FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7) complete. Timing: real 0.014s	user 0.006s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4918,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:55.198522 20539 maintenance_manager.cc:419] P 27f5ebddcd1248449a847a09b52c3c07: Scheduling MajorDeltaCompactionOp(1cb921a51aa142dab23389ba4cba75c7): perf score=1.000000
I20260812 06:17:55.315382 20431 maintenance_manager.cc:643] P 27f5ebddcd1248449a847a09b52c3c07: MajorDeltaCompactionOp(1cb921a51aa142dab23389ba4cba75c7) complete. Timing: real 0.117s	user 0.093s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713263,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":109,"lbm_read_time_us":7804,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22051,"lbm_writes_lt_1ms":443,"mutex_wait_us":51,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12672,"update_count":2000}
I20260812 06:17:55.315900 20539 maintenance_manager.cc:419] P 27f5ebddcd1248449a847a09b52c3c07: Scheduling FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7): perf score=10.126437
I20260812 06:17:55.355944 20431 maintenance_manager.cc:643] P 27f5ebddcd1248449a847a09b52c3c07: FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7) complete. Timing: real 0.040s	user 0.019s	sys 0.012s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":13763,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:55.356492 20539 maintenance_manager.cc:419] P 27f5ebddcd1248449a847a09b52c3c07: Scheduling FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7): perf score=2.188937
I20260812 06:17:55.366093 20431 maintenance_manager.cc:643] P 27f5ebddcd1248449a847a09b52c3c07: FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3573,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:55.366724 20539 maintenance_manager.cc:419] P 27f5ebddcd1248449a847a09b52c3c07: Scheduling FlushMRSOp(1cb921a51aa142dab23389ba4cba75c7): perf score=1.000000
I20260812 06:17:55.395816 20431 maintenance_manager.cc:643] P 27f5ebddcd1248449a847a09b52c3c07: FlushMRSOp(1cb921a51aa142dab23389ba4cba75c7) complete. Timing: real 0.029s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":49,"dirs.run_cpu_time_us":171,"dirs.run_wall_time_us":1561,"drs_written":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1884,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:55.396402 20539 maintenance_manager.cc:419] P 27f5ebddcd1248449a847a09b52c3c07: Scheduling LogGCOp(1cb921a51aa142dab23389ba4cba75c7): free 120553332 bytes of WAL
I20260812 06:17:55.396607 20431 log_reader.cc:385] T 1cb921a51aa142dab23389ba4cba75c7: removed 12 log segments from log reader
I20260812 06:17:55.396651 20431 log.cc:1079] T 1cb921a51aa142dab23389ba4cba75c7 P 27f5ebddcd1248449a847a09b52c3c07: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/1cb921a51aa142dab23389ba4cba75c7/wal-000000015 (ops 72-76)
I20260812 06:17:55.396680 20431 log.cc:1079] T 1cb921a51aa142dab23389ba4cba75c7 P 27f5ebddcd1248449a847a09b52c3c07: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/1cb921a51aa142dab23389ba4cba75c7/wal-000000016 (ops 77-81)
I20260812 06:17:55.396713 20431 log.cc:1079] T 1cb921a51aa142dab23389ba4cba75c7 P 27f5ebddcd1248449a847a09b52c3c07: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/1cb921a51aa142dab23389ba4cba75c7/wal-000000017 (ops 82-86)
I20260812 06:17:55.396745 20431 log.cc:1079] T 1cb921a51aa142dab23389ba4cba75c7 P 27f5ebddcd1248449a847a09b52c3c07: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/1cb921a51aa142dab23389ba4cba75c7/wal-000000018 (ops 87-90)
I20260812 06:17:55.396777 20431 log.cc:1079] T 1cb921a51aa142dab23389ba4cba75c7 P 27f5ebddcd1248449a847a09b52c3c07: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/1cb921a51aa142dab23389ba4cba75c7/wal-000000019 (ops 91-95)
I20260812 06:17:55.396808 20431 log.cc:1079] T 1cb921a51aa142dab23389ba4cba75c7 P 27f5ebddcd1248449a847a09b52c3c07: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/1cb921a51aa142dab23389ba4cba75c7/wal-000000020 (ops 96-100)
I20260812 06:17:55.396842 20431 log.cc:1079] T 1cb921a51aa142dab23389ba4cba75c7 P 27f5ebddcd1248449a847a09b52c3c07: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/1cb921a51aa142dab23389ba4cba75c7/wal-000000021 (ops 101-104)
I20260812 06:17:55.396872 20431 log.cc:1079] T 1cb921a51aa142dab23389ba4cba75c7 P 27f5ebddcd1248449a847a09b52c3c07: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/1cb921a51aa142dab23389ba4cba75c7/wal-000000022 (ops 105-109)
I20260812 06:17:55.396903 20431 log.cc:1079] T 1cb921a51aa142dab23389ba4cba75c7 P 27f5ebddcd1248449a847a09b52c3c07: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/1cb921a51aa142dab23389ba4cba75c7/wal-000000023 (ops 110-114)
I20260812 06:17:55.396934 20431 log.cc:1079] T 1cb921a51aa142dab23389ba4cba75c7 P 27f5ebddcd1248449a847a09b52c3c07: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/1cb921a51aa142dab23389ba4cba75c7/wal-000000024 (ops 115-119)
I20260812 06:17:55.396963 20431 log.cc:1079] T 1cb921a51aa142dab23389ba4cba75c7 P 27f5ebddcd1248449a847a09b52c3c07: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/1cb921a51aa142dab23389ba4cba75c7/wal-000000025 (ops 120-124)
I20260812 06:17:55.397002 20431 log.cc:1079] T 1cb921a51aa142dab23389ba4cba75c7 P 27f5ebddcd1248449a847a09b52c3c07: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/1cb921a51aa142dab23389ba4cba75c7/wal-000000026 (ops 125-129)
I20260812 06:17:55.418669 20431 maintenance_manager.cc:643] P 27f5ebddcd1248449a847a09b52c3c07: LogGCOp(1cb921a51aa142dab23389ba4cba75c7) complete. Timing: real 0.022s	user 0.001s	sys 0.019s Metrics: {}
I20260812 06:17:55.419064 20539 maintenance_manager.cc:419] P 27f5ebddcd1248449a847a09b52c3c07: Scheduling UndoDeltaBlockGCOp(1cb921a51aa142dab23389ba4cba75c7): 462 bytes on disk
I20260812 06:17:55.419529 20431 maintenance_manager.cc:643] P 27f5ebddcd1248449a847a09b52c3c07: UndoDeltaBlockGCOp(1cb921a51aa142dab23389ba4cba75c7) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4}
I20260812 06:17:55.420094 20539 maintenance_manager.cc:419] P 27f5ebddcd1248449a847a09b52c3c07: Scheduling FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7): perf score=3.181125
I20260812 06:17:55.434818 20431 maintenance_manager.cc:643] P 27f5ebddcd1248449a847a09b52c3c07: FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7) complete. Timing: real 0.015s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":3964,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:55.435236 20539 maintenance_manager.cc:419] P 27f5ebddcd1248449a847a09b52c3c07: Scheduling FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7): perf score=2.188937
I20260812 06:17:55.448644 20431 maintenance_manager.cc:643] P 27f5ebddcd1248449a847a09b52c3c07: FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7) complete. Timing: real 0.013s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4785,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:55.449157 20539 maintenance_manager.cc:419] P 27f5ebddcd1248449a847a09b52c3c07: Scheduling MajorDeltaCompactionOp(1cb921a51aa142dab23389ba4cba75c7): perf score=1.000000
I20260812 06:17:55.607010 20431 maintenance_manager.cc:643] P 27f5ebddcd1248449a847a09b52c3c07: MajorDeltaCompactionOp(1cb921a51aa142dab23389ba4cba75c7) complete. Timing: real 0.158s	user 0.139s	sys 0.017s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918326,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":182,"lbm_read_time_us":11048,"lbm_reads_lt_1ms":674,"lbm_write_time_us":32343,"lbm_writes_lt_1ms":643,"mutex_wait_us":2,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3968,"thread_start_us":72,"threads_started":1,"update_count":3000}
I20260812 06:17:55.607513 20539 maintenance_manager.cc:419] P 27f5ebddcd1248449a847a09b52c3c07: Scheduling FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7): perf score=14.095187
I20260812 06:17:55.657648 20431 maintenance_manager.cc:643] P 27f5ebddcd1248449a847a09b52c3c07: FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7) complete. Timing: real 0.050s	user 0.028s	sys 0.015s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19842,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:55.658211 20539 maintenance_manager.cc:419] P 27f5ebddcd1248449a847a09b52c3c07: Scheduling FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7): perf score=2.188937
I20260812 06:17:55.668555 20431 maintenance_manager.cc:643] P 27f5ebddcd1248449a847a09b52c3c07: FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3721,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:55.669173 20539 maintenance_manager.cc:419] P 27f5ebddcd1248449a847a09b52c3c07: Scheduling MajorDeltaCompactionOp(1cb921a51aa142dab23389ba4cba75c7): perf score=1.000000
I20260812 06:17:55.816159 20431 maintenance_manager.cc:643] P 27f5ebddcd1248449a847a09b52c3c07: MajorDeltaCompactionOp(1cb921a51aa142dab23389ba4cba75c7) complete. Timing: real 0.147s	user 0.122s	sys 0.021s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":583,"lbm_read_time_us":11105,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30184,"lbm_writes_lt_1ms":543,"mutex_wait_us":305,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8832,"update_count":2500}
I20260812 06:17:55.816637 20539 maintenance_manager.cc:419] P 27f5ebddcd1248449a847a09b52c3c07: Scheduling FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7): perf score=11.118625
I20260812 06:17:55.860452 20431 maintenance_manager.cc:643] P 27f5ebddcd1248449a847a09b52c3c07: FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7) complete. Timing: real 0.044s	user 0.024s	sys 0.016s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":17092,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:55.860957 20539 maintenance_manager.cc:419] P 27f5ebddcd1248449a847a09b52c3c07: Scheduling FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7): perf score=2.188937
I20260812 06:17:55.875984 20431 maintenance_manager.cc:643] P 27f5ebddcd1248449a847a09b52c3c07: FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7) complete. Timing: real 0.015s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3738,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:55.876487 20539 maintenance_manager.cc:419] P 27f5ebddcd1248449a847a09b52c3c07: Scheduling FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7): perf score=2.188937
I20260812 06:17:55.885282 20431 maintenance_manager.cc:643] P 27f5ebddcd1248449a847a09b52c3c07: FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7) complete. Timing: real 0.009s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3231,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:55.885795 20539 maintenance_manager.cc:419] P 27f5ebddcd1248449a847a09b52c3c07: Scheduling MajorDeltaCompactionOp(1cb921a51aa142dab23389ba4cba75c7): perf score=1.000000
I20260812 06:17:56.026566 20431 maintenance_manager.cc:643] P 27f5ebddcd1248449a847a09b52c3c07: MajorDeltaCompactionOp(1cb921a51aa142dab23389ba4cba75c7) complete. Timing: real 0.141s	user 0.112s	sys 0.028s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815795,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":321,"lbm_read_time_us":9762,"lbm_reads_lt_1ms":573,"lbm_write_time_us":28610,"lbm_writes_lt_1ms":543,"mutex_wait_us":65,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7552,"update_count":2500}
I20260812 06:17:56.027197 20539 maintenance_manager.cc:419] P 27f5ebddcd1248449a847a09b52c3c07: Scheduling FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7): perf score=11.118625
I20260812 06:17:56.069852 20431 maintenance_manager.cc:643] P 27f5ebddcd1248449a847a09b52c3c07: FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7) complete. Timing: real 0.042s	user 0.025s	sys 0.015s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":18477,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":310,"reinsert_count":0,"update_count":1550}
I20260812 06:17:56.070272 20539 maintenance_manager.cc:419] P 27f5ebddcd1248449a847a09b52c3c07: Scheduling FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7): perf score=2.188937
I20260812 06:17:56.087236 20431 maintenance_manager.cc:643] P 27f5ebddcd1248449a847a09b52c3c07: FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7) complete. Timing: real 0.017s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3663,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:56.087805 20539 maintenance_manager.cc:419] P 27f5ebddcd1248449a847a09b52c3c07: Scheduling FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7): perf score=2.188937
I20260812 06:17:56.100823 20431 maintenance_manager.cc:643] P 27f5ebddcd1248449a847a09b52c3c07: FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7) complete. Timing: real 0.013s	user 0.006s	sys 0.006s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4795,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:56.101280 20539 maintenance_manager.cc:419] P 27f5ebddcd1248449a847a09b52c3c07: Scheduling MajorDeltaCompactionOp(1cb921a51aa142dab23389ba4cba75c7): perf score=1.000000
I20260812 06:17:56.262195 20431 maintenance_manager.cc:643] P 27f5ebddcd1248449a847a09b52c3c07: MajorDeltaCompactionOp(1cb921a51aa142dab23389ba4cba75c7) complete. Timing: real 0.161s	user 0.133s	sys 0.014s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815794,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":221,"lbm_read_time_us":9785,"lbm_reads_lt_1ms":573,"lbm_write_time_us":28196,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:56.262873 20539 maintenance_manager.cc:419] P 27f5ebddcd1248449a847a09b52c3c07: Scheduling FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7): perf score=14.095187
I20260812 06:17:56.314219 20431 maintenance_manager.cc:643] P 27f5ebddcd1248449a847a09b52c3c07: FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7) complete. Timing: real 0.051s	user 0.031s	sys 0.007s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18185,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:56.314640 20539 maintenance_manager.cc:419] P 27f5ebddcd1248449a847a09b52c3c07: Scheduling FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7): perf score=2.188937
I20260812 06:17:56.324822 20431 maintenance_manager.cc:643] P 27f5ebddcd1248449a847a09b52c3c07: FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7) complete. Timing: real 0.010s	user 0.008s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3710,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:56.325417 20539 maintenance_manager.cc:419] P 27f5ebddcd1248449a847a09b52c3c07: Scheduling MajorDeltaCompactionOp(1cb921a51aa142dab23389ba4cba75c7): perf score=1.000000
I20260812 06:17:56.494814 20431 maintenance_manager.cc:643] P 27f5ebddcd1248449a847a09b52c3c07: MajorDeltaCompactionOp(1cb921a51aa142dab23389ba4cba75c7) complete. Timing: real 0.169s	user 0.113s	sys 0.054s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":212,"lbm_read_time_us":11666,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28775,"lbm_writes_lt_1ms":543,"mutex_wait_us":42,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4736,"update_count":2500}
I20260812 06:17:56.495383 20539 maintenance_manager.cc:419] P 27f5ebddcd1248449a847a09b52c3c07: Scheduling FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7): perf score=14.095187
I20260812 06:17:56.533875 20431 maintenance_manager.cc:643] P 27f5ebddcd1248449a847a09b52c3c07: FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7) complete. Timing: real 0.038s	user 0.025s	sys 0.011s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":16948,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:56.534420 20539 maintenance_manager.cc:419] P 27f5ebddcd1248449a847a09b52c3c07: Scheduling MajorDeltaCompactionOp(1cb921a51aa142dab23389ba4cba75c7): perf score=1.000000
I20260812 06:17:56.682351 20431 maintenance_manager.cc:643] P 27f5ebddcd1248449a847a09b52c3c07: MajorDeltaCompactionOp(1cb921a51aa142dab23389ba4cba75c7) complete. Timing: real 0.148s	user 0.086s	sys 0.060s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713151,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":169,"lbm_read_time_us":11106,"lbm_reads_lt_1ms":467,"lbm_write_time_us":23413,"lbm_writes_lt_1ms":443,"mutex_wait_us":2,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5760,"update_count":2000}
I20260812 06:17:56.682886 20539 maintenance_manager.cc:419] P 27f5ebddcd1248449a847a09b52c3c07: Scheduling FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7): perf score=11.118625
I20260812 06:17:56.709765 20431 maintenance_manager.cc:643] P 27f5ebddcd1248449a847a09b52c3c07: FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7) complete. Timing: real 0.027s	user 0.013s	sys 0.012s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":11398,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:56.710474 20539 maintenance_manager.cc:419] P 27f5ebddcd1248449a847a09b52c3c07: Scheduling FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7): perf score=2.188937
I20260812 06:17:56.723359 20431 maintenance_manager.cc:643] P 27f5ebddcd1248449a847a09b52c3c07: FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7) complete. Timing: real 0.013s	user 0.007s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4661,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:56.723968 20539 maintenance_manager.cc:419] P 27f5ebddcd1248449a847a09b52c3c07: Scheduling FlushMRSOp(1cb921a51aa142dab23389ba4cba75c7): perf score=1.000000
I20260812 06:17:56.772262 20431 maintenance_manager.cc:643] P 27f5ebddcd1248449a847a09b52c3c07: FlushMRSOp(1cb921a51aa142dab23389ba4cba75c7) complete. Timing: real 0.048s	user 0.022s	sys 0.006s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":53,"dirs.run_cpu_time_us":183,"dirs.run_wall_time_us":1287,"drs_written":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2256,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:56.773084 20539 maintenance_manager.cc:419] P 27f5ebddcd1248449a847a09b52c3c07: Scheduling FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7): perf score=6.157687
I20260812 06:17:56.794559 20431 maintenance_manager.cc:643] P 27f5ebddcd1248449a847a09b52c3c07: FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7) complete. Timing: real 0.021s	user 0.012s	sys 0.006s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":8804,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:17:56.795087 20539 maintenance_manager.cc:419] P 27f5ebddcd1248449a847a09b52c3c07: Scheduling LogGCOp(1cb921a51aa142dab23389ba4cba75c7): free 136728568 bytes of WAL
I20260812 06:17:56.795392 20431 log_reader.cc:385] T 1cb921a51aa142dab23389ba4cba75c7: removed 13 log segments from log reader
I20260812 06:17:56.795440 20431 log.cc:1079] T 1cb921a51aa142dab23389ba4cba75c7 P 27f5ebddcd1248449a847a09b52c3c07: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/1cb921a51aa142dab23389ba4cba75c7/wal-000000027 (ops 130-134)
I20260812 06:17:56.795469 20431 log.cc:1079] T 1cb921a51aa142dab23389ba4cba75c7 P 27f5ebddcd1248449a847a09b52c3c07: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/1cb921a51aa142dab23389ba4cba75c7/wal-000000028 (ops 135-139)
I20260812 06:17:56.795497 20431 log.cc:1079] T 1cb921a51aa142dab23389ba4cba75c7 P 27f5ebddcd1248449a847a09b52c3c07: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/1cb921a51aa142dab23389ba4cba75c7/wal-000000029 (ops 140-144)
I20260812 06:17:56.795528 20431 log.cc:1079] T 1cb921a51aa142dab23389ba4cba75c7 P 27f5ebddcd1248449a847a09b52c3c07: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/1cb921a51aa142dab23389ba4cba75c7/wal-000000030 (ops 145-149)
I20260812 06:17:56.795553 20431 log.cc:1079] T 1cb921a51aa142dab23389ba4cba75c7 P 27f5ebddcd1248449a847a09b52c3c07: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/1cb921a51aa142dab23389ba4cba75c7/wal-000000031 (ops 150-154)
I20260812 06:17:56.795585 20431 log.cc:1079] T 1cb921a51aa142dab23389ba4cba75c7 P 27f5ebddcd1248449a847a09b52c3c07: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/1cb921a51aa142dab23389ba4cba75c7/wal-000000032 (ops 155-159)
I20260812 06:17:56.795617 20431 log.cc:1079] T 1cb921a51aa142dab23389ba4cba75c7 P 27f5ebddcd1248449a847a09b52c3c07: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/1cb921a51aa142dab23389ba4cba75c7/wal-000000033 (ops 160-164)
I20260812 06:17:56.795648 20431 log.cc:1079] T 1cb921a51aa142dab23389ba4cba75c7 P 27f5ebddcd1248449a847a09b52c3c07: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/1cb921a51aa142dab23389ba4cba75c7/wal-000000034 (ops 165-169)
I20260812 06:17:56.795681 20431 log.cc:1079] T 1cb921a51aa142dab23389ba4cba75c7 P 27f5ebddcd1248449a847a09b52c3c07: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/1cb921a51aa142dab23389ba4cba75c7/wal-000000035 (ops 170-174)
I20260812 06:17:56.795732 20431 log.cc:1079] T 1cb921a51aa142dab23389ba4cba75c7 P 27f5ebddcd1248449a847a09b52c3c07: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/1cb921a51aa142dab23389ba4cba75c7/wal-000000036 (ops 175-179)
I20260812 06:17:56.795768 20431 log.cc:1079] T 1cb921a51aa142dab23389ba4cba75c7 P 27f5ebddcd1248449a847a09b52c3c07: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/1cb921a51aa142dab23389ba4cba75c7/wal-000000037 (ops 180-184)
I20260812 06:17:56.795787 20431 log.cc:1079] T 1cb921a51aa142dab23389ba4cba75c7 P 27f5ebddcd1248449a847a09b52c3c07: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/1cb921a51aa142dab23389ba4cba75c7/wal-000000038 (ops 185-189)
I20260812 06:17:56.795861 20431 log.cc:1079] T 1cb921a51aa142dab23389ba4cba75c7 P 27f5ebddcd1248449a847a09b52c3c07: Deleting log segment in path: /tmp/dist-test-taskRw_Ck1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515467054230-19929-0/minicluster-data/ts-0-root/wals/1cb921a51aa142dab23389ba4cba75c7/wal-000000039 (ops 190-194)
I20260812 06:17:56.820679 20431 maintenance_manager.cc:643] P 27f5ebddcd1248449a847a09b52c3c07: LogGCOp(1cb921a51aa142dab23389ba4cba75c7) complete. Timing: real 0.025s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:17:56.821062 20539 maintenance_manager.cc:419] P 27f5ebddcd1248449a847a09b52c3c07: Scheduling UndoDeltaBlockGCOp(1cb921a51aa142dab23389ba4cba75c7): 483 bytes on disk
I20260812 06:17:56.821533 20431 maintenance_manager.cc:643] P 27f5ebddcd1248449a847a09b52c3c07: UndoDeltaBlockGCOp(1cb921a51aa142dab23389ba4cba75c7) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4}
I20260812 06:17:56.822038 20539 maintenance_manager.cc:419] P 27f5ebddcd1248449a847a09b52c3c07: Scheduling FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7): perf score=1.196750
I20260812 06:17:56.830453 20431 maintenance_manager.cc:643] P 27f5ebddcd1248449a847a09b52c3c07: FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7) complete. Timing: real 0.008s	user 0.006s	sys 0.001s Metrics: {"bytes_written":3077034,"delete_count":0,"lbm_write_time_us":2978,"lbm_writes_lt_1ms":78,"reinsert_count":0,"update_count":375}
I20260812 06:17:56.830855 20539 maintenance_manager.cc:419] P 27f5ebddcd1248449a847a09b52c3c07: Scheduling MajorDeltaCompactionOp(1cb921a51aa142dab23389ba4cba75c7): perf score=1.000000
I20260812 06:17:56.967137 19929 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.503s	user 1.651s	sys 0.164s
I20260812 06:17:57.033998 20431 maintenance_manager.cc:643] P 27f5ebddcd1248449a847a09b52c3c07: MajorDeltaCompactionOp(1cb921a51aa142dab23389ba4cba75c7) complete. Timing: real 0.203s	user 0.135s	sys 0.068s Metrics: {"cfile_cache_miss":709,"cfile_cache_miss_bytes":31995113,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":520,"lbm_read_time_us":15593,"lbm_reads_lt_1ms":741,"lbm_write_time_us":32131,"lbm_writes_lt_1ms":718,"mutex_wait_us":57,"peak_mem_usage":84862401,"reinsert_count":0,"spinlock_wait_cycles":10496,"thread_start_us":91,"threads_started":1,"update_count":3375}
I20260812 06:17:57.034549 20539 maintenance_manager.cc:419] P 27f5ebddcd1248449a847a09b52c3c07: Scheduling FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7): perf score=11.118625
I20260812 06:17:57.049278 19929 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.082s	user 0.001s	sys 0.001s
I20260812 06:17:57.049728 19929 tablet_server.cc:179] TabletServer@127.19.118.65:0 shutting down...
I20260812 06:17:57.075325 20431 maintenance_manager.cc:643] P 27f5ebddcd1248449a847a09b52c3c07: FlushDeltaMemStoresOp(1cb921a51aa142dab23389ba4cba75c7) complete. Timing: real 0.041s	user 0.022s	sys 0.015s Metrics: {"bytes_written":13333102,"delete_count":0,"lbm_write_time_us":14269,"lbm_writes_lt_1ms":328,"reinsert_count":0,"update_count":1625}
I20260812 06:17:57.075903 19929 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:57.076107 19929 tablet_replica.cc:333] T 1cb921a51aa142dab23389ba4cba75c7 P 27f5ebddcd1248449a847a09b52c3c07: stopping tablet replica
I20260812 06:17:57.076234 19929 raft_consensus.cc:2243] T 1cb921a51aa142dab23389ba4cba75c7 P 27f5ebddcd1248449a847a09b52c3c07 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:57.076401 19929 raft_consensus.cc:2272] T 1cb921a51aa142dab23389ba4cba75c7 P 27f5ebddcd1248449a847a09b52c3c07 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:57.080529 19929 tablet_server.cc:196] TabletServer@127.19.118.65:0 shutdown complete.
I20260812 06:17:57.089321 19929 master.cc:562] Master@127.19.118.126:37143 shutting down...
I20260812 06:17:57.092442 19929 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 8630735969684cbcb4b36984360b02be [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:57.092577 19929 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 8630735969684cbcb4b36984360b02be [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:57.092624 19929 tablet_replica.cc:333] T 00000000000000000000000000000000 P 8630735969684cbcb4b36984360b02be: stopping tablet replica
I20260812 06:17:57.104511 19929 master.cc:584] Master@127.19.118.126:37143 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (4906 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10112 ms total)

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