[==========] 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:19.492441  1787 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.1.190.254:33465
I20260812 06:17:19.493782  1787 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:19.494544  1787 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:19.502193  1796 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:19.502187  1793 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:19.502285  1787 server_base.cc:1061] running on GCE node
W20260812 06:17:19.502467  1794 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:19.503104  1787 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:19.503216  1787 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:19.503247  1787 hybrid_clock.cc:648] HybridClock initialized: now 1786515439503244 us; error 0 us; skew 500 ppm
I20260812 06:17:19.505594  1787 webserver.cc:533] Webserver started at http://127.1.190.254:43161/ using document root <none> and password file <none>
I20260812 06:17:19.506259  1787 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:19.506337  1787 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:19.506582  1787 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:19.508525  1787 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439479178-1787-0/minicluster-data/master-0-root/instance:
uuid: "7a268c8a2d324753aa2e30dc60b2dad7"
format_stamp: "Formatted at 2026-08-12 06:17:19 on dist-test-slave-77v9"
I20260812 06:17:19.513067  1787 fs_manager.cc:696] Time spent creating directory manager: real 0.004s	user 0.003s	sys 0.001s
I20260812 06:17:19.516054  1802 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:19.518163  1787 fs_manager.cc:730] Time spent opening block manager: real 0.004s	user 0.003s	sys 0.000s
I20260812 06:17:19.518419  1787 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439479178-1787-0/minicluster-data/master-0-root
uuid: "7a268c8a2d324753aa2e30dc60b2dad7"
format_stamp: "Formatted at 2026-08-12 06:17:19 on dist-test-slave-77v9"
I20260812 06:17:19.518575  1787 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439479178-1787-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439479178-1787-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439479178-1787-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:19.541765  1787 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:19.542550  1787 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:19.542970  1787 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:19.554332  1787 rpc_server.cc:307] RPC server started. Bound to: 127.1.190.254:33465
I20260812 06:17:19.554384  1864 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.1.190.254:33465 every 8 connection(s)
I20260812 06:17:19.557451  1865 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:19.564637  1865 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 7a268c8a2d324753aa2e30dc60b2dad7: Bootstrap starting.
I20260812 06:17:19.568310  1865 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 7a268c8a2d324753aa2e30dc60b2dad7: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:19.569749  1865 log.cc:826] T 00000000000000000000000000000000 P 7a268c8a2d324753aa2e30dc60b2dad7: Log is configured to *not* fsync() on all Append() calls
I20260812 06:17:19.572297  1865 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 7a268c8a2d324753aa2e30dc60b2dad7: No bootstrap required, opened a new log
I20260812 06:17:19.575910  1865 raft_consensus.cc:359] T 00000000000000000000000000000000 P 7a268c8a2d324753aa2e30dc60b2dad7 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7a268c8a2d324753aa2e30dc60b2dad7" member_type: VOTER }
I20260812 06:17:19.576315  1865 raft_consensus.cc:385] T 00000000000000000000000000000000 P 7a268c8a2d324753aa2e30dc60b2dad7 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:19.576490  1865 raft_consensus.cc:740] T 00000000000000000000000000000000 P 7a268c8a2d324753aa2e30dc60b2dad7 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 7a268c8a2d324753aa2e30dc60b2dad7, State: Initialized, Role: FOLLOWER
I20260812 06:17:19.577507  1865 consensus_queue.cc:260] T 00000000000000000000000000000000 P 7a268c8a2d324753aa2e30dc60b2dad7 [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: "7a268c8a2d324753aa2e30dc60b2dad7" member_type: VOTER }
I20260812 06:17:19.577724  1865 raft_consensus.cc:399] T 00000000000000000000000000000000 P 7a268c8a2d324753aa2e30dc60b2dad7 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:19.577838  1865 raft_consensus.cc:493] T 00000000000000000000000000000000 P 7a268c8a2d324753aa2e30dc60b2dad7 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:19.578035  1865 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 7a268c8a2d324753aa2e30dc60b2dad7 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:19.579173  1865 raft_consensus.cc:515] T 00000000000000000000000000000000 P 7a268c8a2d324753aa2e30dc60b2dad7 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7a268c8a2d324753aa2e30dc60b2dad7" member_type: VOTER }
I20260812 06:17:19.579806  1865 leader_election.cc:304] T 00000000000000000000000000000000 P 7a268c8a2d324753aa2e30dc60b2dad7 [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: 7a268c8a2d324753aa2e30dc60b2dad7; no voters: 
I20260812 06:17:19.580281  1865 leader_election.cc:290] T 00000000000000000000000000000000 P 7a268c8a2d324753aa2e30dc60b2dad7 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:19.580542  1868 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 7a268c8a2d324753aa2e30dc60b2dad7 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:19.580946  1868 raft_consensus.cc:697] T 00000000000000000000000000000000 P 7a268c8a2d324753aa2e30dc60b2dad7 [term 1 LEADER]: Becoming Leader. State: Replica: 7a268c8a2d324753aa2e30dc60b2dad7, State: Running, Role: LEADER
I20260812 06:17:19.581455  1868 consensus_queue.cc:237] T 00000000000000000000000000000000 P 7a268c8a2d324753aa2e30dc60b2dad7 [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: "7a268c8a2d324753aa2e30dc60b2dad7" member_type: VOTER }
I20260812 06:17:19.581614  1865 sys_catalog.cc:565] T 00000000000000000000000000000000 P 7a268c8a2d324753aa2e30dc60b2dad7 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:19.584534  1870 sys_catalog.cc:455] T 00000000000000000000000000000000 P 7a268c8a2d324753aa2e30dc60b2dad7 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 7a268c8a2d324753aa2e30dc60b2dad7. Latest consensus state: current_term: 1 leader_uuid: "7a268c8a2d324753aa2e30dc60b2dad7" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7a268c8a2d324753aa2e30dc60b2dad7" member_type: VOTER } }
I20260812 06:17:19.584713  1870 sys_catalog.cc:458] T 00000000000000000000000000000000 P 7a268c8a2d324753aa2e30dc60b2dad7 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:19.584671  1869 sys_catalog.cc:455] T 00000000000000000000000000000000 P 7a268c8a2d324753aa2e30dc60b2dad7 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "7a268c8a2d324753aa2e30dc60b2dad7" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7a268c8a2d324753aa2e30dc60b2dad7" member_type: VOTER } }
I20260812 06:17:19.584857  1869 sys_catalog.cc:458] T 00000000000000000000000000000000 P 7a268c8a2d324753aa2e30dc60b2dad7 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:19.585098  1787 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:19.585408  1884 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:19.588102  1884 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:19.595625  1884 catalog_manager.cc:1383] Generated new cluster ID: ad7f4074702b40ef9bb353ab484c4d7d
I20260812 06:17:19.595764  1884 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:19.613370  1884 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:19.614527  1884 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:19.624303  1884 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 7a268c8a2d324753aa2e30dc60b2dad7: Generated new TSK 0
I20260812 06:17:19.625218  1884 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:19.650911  1787 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:19.654187  1892 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:19.654352  1889 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:19.654357  1890 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:19.655203  1787 server_base.cc:1061] running on GCE node
I20260812 06:17:19.655436  1787 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:19.655503  1787 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:19.655531  1787 hybrid_clock.cc:648] HybridClock initialized: now 1786515439655530 us; error 0 us; skew 500 ppm
I20260812 06:17:19.657044  1787 webserver.cc:533] Webserver started at http://127.1.190.193:34419/ using document root <none> and password file <none>
I20260812 06:17:19.657261  1787 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:19.657336  1787 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:19.657425  1787 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:19.657897  1787 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439479178-1787-0/minicluster-data/ts-0-root/instance:
uuid: "c3d6d8e15a714a2f84729051e2c047c0"
format_stamp: "Formatted at 2026-08-12 06:17:19 on dist-test-slave-77v9"
I20260812 06:17:19.660123  1787 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:17:19.662379  1898 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:19.663188  1787 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.000s	sys 0.001s
I20260812 06:17:19.663332  1787 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439479178-1787-0/minicluster-data/ts-0-root
uuid: "c3d6d8e15a714a2f84729051e2c047c0"
format_stamp: "Formatted at 2026-08-12 06:17:19 on dist-test-slave-77v9"
I20260812 06:17:19.663489  1787 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439479178-1787-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439479178-1787-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439479178-1787-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:19.678606  1787 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:19.679301  1787 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:19.679994  1787 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:19.681136  1787 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:19.681201  1787 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:19.681291  1787 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:19.681342  1787 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:19.690886  1787 rpc_server.cc:307] RPC server started. Bound to: 127.1.190.193:41575
I20260812 06:17:19.690899  1969 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.1.190.193:41575 every 8 connection(s)
I20260812 06:17:19.703788  1970 heartbeater.cc:344] Connected to a master server at 127.1.190.254:33465
I20260812 06:17:19.704221  1970 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:19.704919  1970 heartbeater.cc:507] Master 127.1.190.254:33465 requested a full tablet report, sending...
I20260812 06:17:19.706887  1821 ts_manager.cc:194] Registered new tserver with Master: c3d6d8e15a714a2f84729051e2c047c0 (127.1.190.193:41575)
I20260812 06:17:19.707224  1787 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.015586009s
I20260812 06:17:19.709004  1821 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:47530
I20260812 06:17:19.722693  1821 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:47546:
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:19.742667  1930 tablet_service.cc:1511] Processing CreateTablet for tablet c74ae2da387b4e7ea9cd664670f5bd78 (DEFAULT_TABLE table=heavy-update-compaction-test [id=dc5cb8838d2548a18b689aa7538bf8b9]), partition=
I20260812 06:17:19.743355  1930 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet c74ae2da387b4e7ea9cd664670f5bd78. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:19.747144  1984 tablet_bootstrap.cc:492] T c74ae2da387b4e7ea9cd664670f5bd78 P c3d6d8e15a714a2f84729051e2c047c0: Bootstrap starting.
I20260812 06:17:19.748245  1984 tablet_bootstrap.cc:654] T c74ae2da387b4e7ea9cd664670f5bd78 P c3d6d8e15a714a2f84729051e2c047c0: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:19.750200  1984 tablet_bootstrap.cc:492] T c74ae2da387b4e7ea9cd664670f5bd78 P c3d6d8e15a714a2f84729051e2c047c0: No bootstrap required, opened a new log
I20260812 06:17:19.750380  1984 ts_tablet_manager.cc:1403] T c74ae2da387b4e7ea9cd664670f5bd78 P c3d6d8e15a714a2f84729051e2c047c0: Time spent bootstrapping tablet: real 0.003s	user 0.000s	sys 0.002s
I20260812 06:17:19.751065  1984 raft_consensus.cc:359] T c74ae2da387b4e7ea9cd664670f5bd78 P c3d6d8e15a714a2f84729051e2c047c0 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c3d6d8e15a714a2f84729051e2c047c0" member_type: VOTER last_known_addr { host: "127.1.190.193" port: 41575 } }
I20260812 06:17:19.751236  1984 raft_consensus.cc:385] T c74ae2da387b4e7ea9cd664670f5bd78 P c3d6d8e15a714a2f84729051e2c047c0 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:19.751305  1984 raft_consensus.cc:740] T c74ae2da387b4e7ea9cd664670f5bd78 P c3d6d8e15a714a2f84729051e2c047c0 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: c3d6d8e15a714a2f84729051e2c047c0, State: Initialized, Role: FOLLOWER
I20260812 06:17:19.751484  1984 consensus_queue.cc:260] T c74ae2da387b4e7ea9cd664670f5bd78 P c3d6d8e15a714a2f84729051e2c047c0 [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: "c3d6d8e15a714a2f84729051e2c047c0" member_type: VOTER last_known_addr { host: "127.1.190.193" port: 41575 } }
I20260812 06:17:19.751590  1984 raft_consensus.cc:399] T c74ae2da387b4e7ea9cd664670f5bd78 P c3d6d8e15a714a2f84729051e2c047c0 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:19.751650  1984 raft_consensus.cc:493] T c74ae2da387b4e7ea9cd664670f5bd78 P c3d6d8e15a714a2f84729051e2c047c0 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:19.751714  1984 raft_consensus.cc:3060] T c74ae2da387b4e7ea9cd664670f5bd78 P c3d6d8e15a714a2f84729051e2c047c0 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:19.752624  1984 raft_consensus.cc:515] T c74ae2da387b4e7ea9cd664670f5bd78 P c3d6d8e15a714a2f84729051e2c047c0 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c3d6d8e15a714a2f84729051e2c047c0" member_type: VOTER last_known_addr { host: "127.1.190.193" port: 41575 } }
I20260812 06:17:19.752821  1984 leader_election.cc:304] T c74ae2da387b4e7ea9cd664670f5bd78 P c3d6d8e15a714a2f84729051e2c047c0 [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: c3d6d8e15a714a2f84729051e2c047c0; no voters: 
I20260812 06:17:19.753140  1984 leader_election.cc:290] T c74ae2da387b4e7ea9cd664670f5bd78 P c3d6d8e15a714a2f84729051e2c047c0 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:19.753358  1986 raft_consensus.cc:2804] T c74ae2da387b4e7ea9cd664670f5bd78 P c3d6d8e15a714a2f84729051e2c047c0 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:19.753559  1984 ts_tablet_manager.cc:1434] T c74ae2da387b4e7ea9cd664670f5bd78 P c3d6d8e15a714a2f84729051e2c047c0: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.001s
I20260812 06:17:19.753695  1986 raft_consensus.cc:697] T c74ae2da387b4e7ea9cd664670f5bd78 P c3d6d8e15a714a2f84729051e2c047c0 [term 1 LEADER]: Becoming Leader. State: Replica: c3d6d8e15a714a2f84729051e2c047c0, State: Running, Role: LEADER
I20260812 06:17:19.753829  1970 heartbeater.cc:499] Master 127.1.190.254:33465 was elected leader, sending a full tablet report...
I20260812 06:17:19.754086  1986 consensus_queue.cc:237] T c74ae2da387b4e7ea9cd664670f5bd78 P c3d6d8e15a714a2f84729051e2c047c0 [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: "c3d6d8e15a714a2f84729051e2c047c0" member_type: VOTER last_known_addr { host: "127.1.190.193" port: 41575 } }
I20260812 06:17:19.757714  1821 catalog_manager.cc:5719] T c74ae2da387b4e7ea9cd664670f5bd78 P c3d6d8e15a714a2f84729051e2c047c0 reported cstate change: term changed from 0 to 1, leader changed from <none> to c3d6d8e15a714a2f84729051e2c047c0 (127.1.190.193). New cstate: current_term: 1 leader_uuid: "c3d6d8e15a714a2f84729051e2c047c0" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c3d6d8e15a714a2f84729051e2c047c0" member_type: VOTER last_known_addr { host: "127.1.190.193" port: 41575 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:19.839821  1787 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.074s	user 0.024s	sys 0.014s
I20260812 06:17:19.942487  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling FlushMRSOp(c74ae2da387b4e7ea9cd664670f5bd78): perf score=10.125253
I20260812 06:17:20.090720  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: FlushMRSOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.148s	user 0.102s	sys 0.043s Metrics: {"bytes_written":8205078,"cfile_init":1,"compiler_manager_pool.queue_time_us":286,"delete_count":0,"dirs.queue_time_us":93,"dirs.run_cpu_time_us":301,"dirs.run_wall_time_us":1175,"drs_written":1,"lbm_read_time_us":91,"lbm_reads_lt_1ms":4,"lbm_write_time_us":31307,"lbm_writes_lt_1ms":457,"peak_mem_usage":0,"reinsert_count":0,"rows_written":102,"thread_start_us":172,"threads_started":1,"update_count":1000}
I20260812 06:17:20.092306  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling LogGCOp(c74ae2da387b4e7ea9cd664670f5bd78): free 11976772 bytes of WAL
I20260812 06:17:20.092762  1903 log_reader.cc:385] T c74ae2da387b4e7ea9cd664670f5bd78: removed 1 log segments from log reader
I20260812 06:17:20.092958  1903 log.cc:1079] T c74ae2da387b4e7ea9cd664670f5bd78 P c3d6d8e15a714a2f84729051e2c047c0: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/c74ae2da387b4e7ea9cd664670f5bd78/wal-000000001 (ops 1-6)
I20260812 06:17:20.096565  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: LogGCOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.004s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:17:20.097119  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling UndoDeltaBlockGCOp(c74ae2da387b4e7ea9cd664670f5bd78): 8206537 bytes on disk
I20260812 06:17:20.097813  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: UndoDeltaBlockGCOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":87,"lbm_reads_lt_1ms":4}
I20260812 06:17:20.098304  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78): perf score=2.188937
I20260812 06:17:20.125923  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.027s	user 0.005s	sys 0.010s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6373,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:20.126664  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78): perf score=2.188937
I20260812 06:17:20.145854  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.019s	user 0.005s	sys 0.013s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":7265,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:20.146827  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling MajorDeltaCompactionOp(c74ae2da387b4e7ea9cd664670f5bd78): perf score=1.000000
I20260812 06:17:20.322916  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: MajorDeltaCompactionOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.176s	user 0.125s	sys 0.040s Metrics: {"cfile_cache_miss":433,"cfile_cache_miss_bytes":20590464,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1262,"lbm_read_time_us":11530,"lbm_reads_lt_1ms":469,"lbm_write_time_us":29138,"lbm_writes_lt_1ms":443,"mutex_wait_us":302,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1408,"thread_start_us":455,"threads_started":5,"update_count":2000}
I20260812 06:17:20.323926  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78): perf score=10.126437
I20260812 06:17:20.379590  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.055s	user 0.021s	sys 0.021s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19118,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:20.380357  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78): perf score=2.188937
I20260812 06:17:20.401897  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.021s	user 0.020s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7638,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:20.402511  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling MajorDeltaCompactionOp(c74ae2da387b4e7ea9cd664670f5bd78): perf score=1.000000
I20260812 06:17:20.557689  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: MajorDeltaCompactionOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.155s	user 0.128s	sys 0.023s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590347,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":3075,"lbm_read_time_us":10860,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29914,"lbm_writes_lt_1ms":443,"mutex_wait_us":1028,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":138496,"update_count":2000}
I20260812 06:17:20.558483  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78): perf score=10.126437
I20260812 06:17:20.623010  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.064s	user 0.029s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19502,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:20.623857  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78): perf score=2.188937
I20260812 06:17:20.638222  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.014s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5503,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:20.638805  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling MajorDeltaCompactionOp(c74ae2da387b4e7ea9cd664670f5bd78): perf score=1.000000
I20260812 06:17:20.822695  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: MajorDeltaCompactionOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.184s	user 0.114s	sys 0.063s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590347,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1296,"lbm_read_time_us":12004,"lbm_reads_lt_1ms":472,"lbm_write_time_us":32327,"lbm_writes_lt_1ms":443,"mutex_wait_us":451,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:20.823943  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78): perf score=7.149875
I20260812 06:17:20.852993  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.029s	user 0.022s	sys 0.007s Metrics: {"bytes_written":8656348,"delete_count":0,"lbm_write_time_us":11249,"lbm_writes_lt_1ms":214,"reinsert_count":0,"update_count":1055}
I20260812 06:17:20.853943  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78): perf score=2.188937
I20260812 06:17:20.873860  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.020s	user 0.018s	sys 0.000s Metrics: {"bytes_written":3651380,"delete_count":0,"lbm_write_time_us":7730,"lbm_writes_lt_1ms":92,"reinsert_count":0,"update_count":445}
I20260812 06:17:20.875066  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling MajorDeltaCompactionOp(c74ae2da387b4e7ea9cd664670f5bd78): perf score=1.000000
I20260812 06:17:21.004280  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: MajorDeltaCompactionOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.129s	user 0.099s	sys 0.027s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16487926,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1245,"lbm_read_time_us":8595,"lbm_reads_lt_1ms":364,"lbm_write_time_us":23035,"lbm_writes_lt_1ms":343,"mutex_wait_us":339,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":6912,"update_count":1500}
I20260812 06:17:21.005198  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78): perf score=10.126437
I20260812 06:17:21.050112  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.045s	user 0.024s	sys 0.017s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18151,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:21.050766  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling MajorDeltaCompactionOp(c74ae2da387b4e7ea9cd664670f5bd78): perf score=1.000000
I20260812 06:17:21.174759  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: MajorDeltaCompactionOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.124s	user 0.107s	sys 0.016s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16487816,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":455,"lbm_read_time_us":8376,"lbm_reads_lt_1ms":363,"lbm_write_time_us":21488,"lbm_writes_lt_1ms":343,"mutex_wait_us":77,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":19712,"update_count":1500}
I20260812 06:17:21.175650  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78): perf score=10.126437
I20260812 06:17:21.217482  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.042s	user 0.032s	sys 0.008s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":17838,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:21.218135  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78): perf score=2.188937
I20260812 06:17:21.235172  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.017s	user 0.002s	sys 0.012s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5555,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:21.235909  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling MajorDeltaCompactionOp(c74ae2da387b4e7ea9cd664670f5bd78): perf score=1.000000
I20260812 06:17:21.387632  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: MajorDeltaCompactionOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.151s	user 0.132s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590348,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":948,"lbm_read_time_us":10565,"lbm_reads_lt_1ms":472,"lbm_write_time_us":30784,"lbm_writes_lt_1ms":443,"mutex_wait_us":238,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":21888,"update_count":2000}
I20260812 06:17:21.388492  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78): perf score=10.126437
I20260812 06:17:21.447459  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.059s	user 0.029s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20763,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:21.448169  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78): perf score=2.188937
I20260812 06:17:21.461736  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.013s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5084,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:21.462466  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling MajorDeltaCompactionOp(c74ae2da387b4e7ea9cd664670f5bd78): perf score=1.000000
I20260812 06:17:21.623661  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: MajorDeltaCompactionOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.161s	user 0.120s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590347,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":971,"lbm_read_time_us":11220,"lbm_reads_lt_1ms":472,"lbm_write_time_us":33514,"lbm_writes_lt_1ms":443,"mutex_wait_us":27,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":20224,"update_count":2000}
I20260812 06:17:21.624459  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78): perf score=10.126437
I20260812 06:17:21.677784  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.053s	user 0.029s	sys 0.023s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":25436,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":300,"reinsert_count":0,"update_count":1500}
I20260812 06:17:21.678543  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78): perf score=2.188937
I20260812 06:17:21.694581  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.016s	user 0.005s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5741,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:21.695133  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling FlushMRSOp(c74ae2da387b4e7ea9cd664670f5bd78): perf score=1.000000
I20260812 06:17:21.731596  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: FlushMRSOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.036s	user 0.034s	sys 0.000s Metrics: {"bytes_written":1234474,"cfile_init":1,"dirs.queue_time_us":114,"dirs.run_cpu_time_us":415,"dirs.run_wall_time_us":2100,"drs_written":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1789,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:17:21.732753  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling LogGCOp(c74ae2da387b4e7ea9cd664670f5bd78): free 121459489 bytes of WAL
I20260812 06:17:21.733129  1903 log_reader.cc:385] T c74ae2da387b4e7ea9cd664670f5bd78: removed 12 log segments from log reader
I20260812 06:17:21.733180  1903 log.cc:1079] T c74ae2da387b4e7ea9cd664670f5bd78 P c3d6d8e15a714a2f84729051e2c047c0: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/c74ae2da387b4e7ea9cd664670f5bd78/wal-000000002 (ops 7-11)
I20260812 06:17:21.733215  1903 log.cc:1079] T c74ae2da387b4e7ea9cd664670f5bd78 P c3d6d8e15a714a2f84729051e2c047c0: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/c74ae2da387b4e7ea9cd664670f5bd78/wal-000000003 (ops 12-16)
I20260812 06:17:21.733292  1903 log.cc:1079] T c74ae2da387b4e7ea9cd664670f5bd78 P c3d6d8e15a714a2f84729051e2c047c0: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/c74ae2da387b4e7ea9cd664670f5bd78/wal-000000004 (ops 17-21)
I20260812 06:17:21.733347  1903 log.cc:1079] T c74ae2da387b4e7ea9cd664670f5bd78 P c3d6d8e15a714a2f84729051e2c047c0: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/c74ae2da387b4e7ea9cd664670f5bd78/wal-000000005 (ops 22-26)
I20260812 06:17:21.733369  1903 log.cc:1079] T c74ae2da387b4e7ea9cd664670f5bd78 P c3d6d8e15a714a2f84729051e2c047c0: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/c74ae2da387b4e7ea9cd664670f5bd78/wal-000000006 (ops 27-31)
I20260812 06:17:21.733434  1903 log.cc:1079] T c74ae2da387b4e7ea9cd664670f5bd78 P c3d6d8e15a714a2f84729051e2c047c0: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/c74ae2da387b4e7ea9cd664670f5bd78/wal-000000007 (ops 32-36)
I20260812 06:17:21.733480  1903 log.cc:1079] T c74ae2da387b4e7ea9cd664670f5bd78 P c3d6d8e15a714a2f84729051e2c047c0: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/c74ae2da387b4e7ea9cd664670f5bd78/wal-000000008 (ops 37-41)
I20260812 06:17:21.733525  1903 log.cc:1079] T c74ae2da387b4e7ea9cd664670f5bd78 P c3d6d8e15a714a2f84729051e2c047c0: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/c74ae2da387b4e7ea9cd664670f5bd78/wal-000000009 (ops 42-46)
I20260812 06:17:21.733575  1903 log.cc:1079] T c74ae2da387b4e7ea9cd664670f5bd78 P c3d6d8e15a714a2f84729051e2c047c0: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/c74ae2da387b4e7ea9cd664670f5bd78/wal-000000010 (ops 47-51)
I20260812 06:17:21.733623  1903 log.cc:1079] T c74ae2da387b4e7ea9cd664670f5bd78 P c3d6d8e15a714a2f84729051e2c047c0: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/c74ae2da387b4e7ea9cd664670f5bd78/wal-000000011 (ops 52-56)
I20260812 06:17:21.733668  1903 log.cc:1079] T c74ae2da387b4e7ea9cd664670f5bd78 P c3d6d8e15a714a2f84729051e2c047c0: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/c74ae2da387b4e7ea9cd664670f5bd78/wal-000000012 (ops 57-61)
I20260812 06:17:21.733714  1903 log.cc:1079] T c74ae2da387b4e7ea9cd664670f5bd78 P c3d6d8e15a714a2f84729051e2c047c0: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/c74ae2da387b4e7ea9cd664670f5bd78/wal-000000013 (ops 62-66)
I20260812 06:17:21.766875  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: LogGCOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.034s	user 0.000s	sys 0.032s Metrics: {}
I20260812 06:17:21.767390  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling UndoDeltaBlockGCOp(c74ae2da387b4e7ea9cd664670f5bd78): 473 bytes on disk
I20260812 06:17:21.768009  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: UndoDeltaBlockGCOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":114,"lbm_reads_lt_1ms":4}
I20260812 06:17:21.768587  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78): perf score=5.165500
I20260812 06:17:21.793804  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.025s	user 0.017s	sys 0.007s Metrics: {"bytes_written":7261522,"delete_count":0,"lbm_write_time_us":10471,"lbm_writes_lt_1ms":180,"reinsert_count":0,"update_count":885}
I20260812 06:17:21.794883  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling MajorDeltaCompactionOp(c74ae2da387b4e7ea9cd664670f5bd78): perf score=1.000000
I20260812 06:17:21.988289  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: MajorDeltaCompactionOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.193s	user 0.126s	sys 0.063s Metrics: {"cfile_cache_miss":610,"cfile_cache_miss_bytes":27851736,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":867,"lbm_read_time_us":14640,"lbm_reads_lt_1ms":646,"lbm_write_time_us":37508,"lbm_writes_lt_1ms":620,"mutex_wait_us":134,"peak_mem_usage":72517899,"reinsert_count":0,"spinlock_wait_cycles":8064,"thread_start_us":98,"threads_started":1,"update_count":2885}
I20260812 06:17:21.989265  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78): perf score=15.087375
I20260812 06:17:22.057106  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.068s	user 0.042s	sys 0.025s Metrics: {"bytes_written":17353459,"delete_count":0,"lbm_write_time_us":29065,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":425,"reinsert_count":0,"update_count":2115}
I20260812 06:17:22.057875  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78): perf score=2.188937
I20260812 06:17:22.080586  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.022s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6434,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:22.081272  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling MajorDeltaCompactionOp(c74ae2da387b4e7ea9cd664670f5bd78): perf score=1.000000
I20260812 06:17:22.276039  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: MajorDeltaCompactionOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.195s	user 0.164s	sys 0.026s Metrics: {"cfile_cache_miss":555,"cfile_cache_miss_bytes":25636316,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1001,"lbm_read_time_us":14219,"lbm_reads_lt_1ms":587,"lbm_write_time_us":40203,"lbm_writes_lt_1ms":566,"mutex_wait_us":395,"peak_mem_usage":65100089,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2615}
I20260812 06:17:22.276795  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78): perf score=14.095187
I20260812 06:17:22.344383  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.067s	user 0.042s	sys 0.012s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":25667,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:22.345058  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78): perf score=2.188937
I20260812 06:17:22.357468  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.012s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4539,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:22.358237  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling MajorDeltaCompactionOp(c74ae2da387b4e7ea9cd664670f5bd78): perf score=1.000000
I20260812 06:17:22.565198  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: MajorDeltaCompactionOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.207s	user 0.126s	sys 0.072s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24692760,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":2004,"lbm_read_time_us":11926,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34922,"lbm_writes_lt_1ms":543,"mutex_wait_us":522,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9216,"update_count":2500}
I20260812 06:17:22.566092  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78): perf score=14.095187
I20260812 06:17:22.628309  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.062s	user 0.022s	sys 0.029s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":25085,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:22.629099  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling MajorDeltaCompactionOp(c74ae2da387b4e7ea9cd664670f5bd78): perf score=1.000000
I20260812 06:17:22.802191  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: MajorDeltaCompactionOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.173s	user 0.112s	sys 0.046s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20590226,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":666,"lbm_read_time_us":11280,"lbm_reads_lt_1ms":463,"lbm_write_time_us":29168,"lbm_writes_lt_1ms":443,"mutex_wait_us":69,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":46336,"update_count":2000}
I20260812 06:17:22.802973  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78): perf score=14.095187
I20260812 06:17:22.866282  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.063s	user 0.024s	sys 0.028s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24369,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:22.866941  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78): perf score=2.188937
I20260812 06:17:22.882330  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.015s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5360,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:22.883973  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling MajorDeltaCompactionOp(c74ae2da387b4e7ea9cd664670f5bd78): perf score=1.000000
I20260812 06:17:23.098191  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: MajorDeltaCompactionOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.214s	user 0.146s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24692757,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":278,"lbm_read_time_us":13038,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32632,"lbm_writes_lt_1ms":543,"mutex_wait_us":50,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2500}
I20260812 06:17:23.098896  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78): perf score=14.095187
I20260812 06:17:23.159065  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.060s	user 0.023s	sys 0.032s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":29265,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":400,"reinsert_count":0,"update_count":2000}
I20260812 06:17:23.160041  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78): perf score=2.188937
I20260812 06:17:23.172432  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.012s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4441,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:23.173192  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling MajorDeltaCompactionOp(c74ae2da387b4e7ea9cd664670f5bd78): perf score=1.000000
I20260812 06:17:23.358359  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: MajorDeltaCompactionOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.185s	user 0.160s	sys 0.024s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24692759,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":792,"lbm_read_time_us":13448,"lbm_reads_lt_1ms":572,"lbm_write_time_us":39743,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3712,"update_count":2500}
I20260812 06:17:23.359834  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78): perf score=10.126437
I20260812 06:17:23.404119  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.043s	user 0.021s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17668,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:23.405033  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78): perf score=2.188937
I20260812 06:17:23.441378  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.036s	user 0.008s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6569,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:23.441993  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78): perf score=2.188937
I20260812 06:17:23.456030  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.014s	user 0.004s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5056,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:23.457008  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling FlushMRSOp(c74ae2da387b4e7ea9cd664670f5bd78): perf score=1.000000
I20260812 06:17:23.493248  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: FlushMRSOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.036s	user 0.027s	sys 0.008s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":106,"dirs.run_cpu_time_us":319,"dirs.run_wall_time_us":1645,"drs_written":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2460,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:23.494239  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling LogGCOp(c74ae2da387b4e7ea9cd664670f5bd78): free 128867456 bytes of WAL
I20260812 06:17:23.494580  1903 log_reader.cc:385] T c74ae2da387b4e7ea9cd664670f5bd78: removed 13 log segments from log reader
I20260812 06:17:23.494639  1903 log.cc:1079] T c74ae2da387b4e7ea9cd664670f5bd78 P c3d6d8e15a714a2f84729051e2c047c0: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/c74ae2da387b4e7ea9cd664670f5bd78/wal-000000014 (ops 67-70)
I20260812 06:17:23.494674  1903 log.cc:1079] T c74ae2da387b4e7ea9cd664670f5bd78 P c3d6d8e15a714a2f84729051e2c047c0: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/c74ae2da387b4e7ea9cd664670f5bd78/wal-000000015 (ops 71-75)
I20260812 06:17:23.494745  1903 log.cc:1079] T c74ae2da387b4e7ea9cd664670f5bd78 P c3d6d8e15a714a2f84729051e2c047c0: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/c74ae2da387b4e7ea9cd664670f5bd78/wal-000000016 (ops 76-80)
I20260812 06:17:23.494796  1903 log.cc:1079] T c74ae2da387b4e7ea9cd664670f5bd78 P c3d6d8e15a714a2f84729051e2c047c0: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/c74ae2da387b4e7ea9cd664670f5bd78/wal-000000017 (ops 81-85)
I20260812 06:17:23.494850  1903 log.cc:1079] T c74ae2da387b4e7ea9cd664670f5bd78 P c3d6d8e15a714a2f84729051e2c047c0: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/c74ae2da387b4e7ea9cd664670f5bd78/wal-000000018 (ops 86-90)
I20260812 06:17:23.494920  1903 log.cc:1079] T c74ae2da387b4e7ea9cd664670f5bd78 P c3d6d8e15a714a2f84729051e2c047c0: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/c74ae2da387b4e7ea9cd664670f5bd78/wal-000000019 (ops 91-95)
I20260812 06:17:23.494969  1903 log.cc:1079] T c74ae2da387b4e7ea9cd664670f5bd78 P c3d6d8e15a714a2f84729051e2c047c0: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/c74ae2da387b4e7ea9cd664670f5bd78/wal-000000020 (ops 96-100)
I20260812 06:17:23.495041  1903 log.cc:1079] T c74ae2da387b4e7ea9cd664670f5bd78 P c3d6d8e15a714a2f84729051e2c047c0: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/c74ae2da387b4e7ea9cd664670f5bd78/wal-000000021 (ops 101-104)
I20260812 06:17:23.495090  1903 log.cc:1079] T c74ae2da387b4e7ea9cd664670f5bd78 P c3d6d8e15a714a2f84729051e2c047c0: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/c74ae2da387b4e7ea9cd664670f5bd78/wal-000000022 (ops 105-109)
I20260812 06:17:23.495138  1903 log.cc:1079] T c74ae2da387b4e7ea9cd664670f5bd78 P c3d6d8e15a714a2f84729051e2c047c0: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/c74ae2da387b4e7ea9cd664670f5bd78/wal-000000023 (ops 110-114)
I20260812 06:17:23.495185  1903 log.cc:1079] T c74ae2da387b4e7ea9cd664670f5bd78 P c3d6d8e15a714a2f84729051e2c047c0: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/c74ae2da387b4e7ea9cd664670f5bd78/wal-000000024 (ops 115-118)
I20260812 06:17:23.495235  1903 log.cc:1079] T c74ae2da387b4e7ea9cd664670f5bd78 P c3d6d8e15a714a2f84729051e2c047c0: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/c74ae2da387b4e7ea9cd664670f5bd78/wal-000000025 (ops 119-123)
I20260812 06:17:23.495294  1903 log.cc:1079] T c74ae2da387b4e7ea9cd664670f5bd78 P c3d6d8e15a714a2f84729051e2c047c0: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/c74ae2da387b4e7ea9cd664670f5bd78/wal-000000026 (ops 124-128)
I20260812 06:17:23.527630  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: LogGCOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.033s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:17:23.528213  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78): perf score=3.181125
I20260812 06:17:23.542819  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":5571,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:23.543395  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78): perf score=2.188937
I20260812 06:17:23.567873  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.024s	user 0.007s	sys 0.014s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4291,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:23.568769  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling MajorDeltaCompactionOp(c74ae2da387b4e7ea9cd664670f5bd78): perf score=1.000000
I20260812 06:17:23.840651  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: MajorDeltaCompactionOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.272s	user 0.166s	sys 0.101s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32897930,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":1023,"lbm_read_time_us":19751,"lbm_reads_lt_1ms":775,"lbm_write_time_us":44875,"lbm_writes_lt_1ms":743,"mutex_wait_us":92,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":5632,"thread_start_us":89,"threads_started":1,"update_count":3500}
I20260812 06:17:23.841615  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78): perf score=15.087375
I20260812 06:17:23.907044  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.065s	user 0.043s	sys 0.019s Metrics: {"bytes_written":16820144,"delete_count":0,"lbm_write_time_us":30903,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":411,"reinsert_count":0,"update_count":2050}
I20260812 06:17:23.907794  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78): perf score=2.188937
I20260812 06:17:23.928309  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.020s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4530,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:23.928979  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78): perf score=2.188937
I20260812 06:17:23.940719  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.012s	user 0.001s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4461,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:23.941457  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling UndoDeltaBlockGCOp(c74ae2da387b4e7ea9cd664670f5bd78): 483 bytes on disk
I20260812 06:17:23.941979  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: UndoDeltaBlockGCOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":67,"lbm_reads_lt_1ms":4}
I20260812 06:17:23.942569  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling MajorDeltaCompactionOp(c74ae2da387b4e7ea9cd664670f5bd78): perf score=1.000000
I20260812 06:17:24.185941  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: MajorDeltaCompactionOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.243s	user 0.151s	sys 0.091s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28795278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":690,"lbm_read_time_us":17128,"lbm_reads_lt_1ms":673,"lbm_write_time_us":39168,"lbm_writes_lt_1ms":643,"mutex_wait_us":36,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":14208,"update_count":3000}
I20260812 06:17:24.186699  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78): perf score=14.095187
I20260812 06:17:24.243321  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.056s	user 0.034s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24865,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:24.244165  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78): perf score=2.188937
I20260812 06:17:24.263540  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.019s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7662,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:24.264329  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling MajorDeltaCompactionOp(c74ae2da387b4e7ea9cd664670f5bd78): perf score=1.000000
I20260812 06:17:24.486644  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: MajorDeltaCompactionOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.222s	user 0.137s	sys 0.079s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24692758,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":315,"lbm_read_time_us":14506,"lbm_reads_lt_1ms":572,"lbm_write_time_us":39220,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":29184,"update_count":2500}
I20260812 06:17:24.487721  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78): perf score=14.095187
I20260812 06:17:24.562381  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.074s	user 0.041s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24957,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:24.563189  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78): perf score=2.188937
I20260812 06:17:24.585315  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.022s	user 0.018s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":8637,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:24.586112  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling MajorDeltaCompactionOp(c74ae2da387b4e7ea9cd664670f5bd78): perf score=1.000000
I20260812 06:17:24.818912  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: MajorDeltaCompactionOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.233s	user 0.167s	sys 0.051s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24692758,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":459,"lbm_read_time_us":17808,"lbm_reads_lt_1ms":572,"lbm_write_time_us":39933,"lbm_writes_lt_1ms":543,"mutex_wait_us":67,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":22144,"update_count":2500}
I20260812 06:17:24.819625  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78): perf score=14.095187
I20260812 06:17:24.893884  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.074s	user 0.030s	sys 0.043s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":27204,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:17:24.894829  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78): perf score=2.188937
I20260812 06:17:24.911677  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.017s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5559,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:24.912370  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling MajorDeltaCompactionOp(c74ae2da387b4e7ea9cd664670f5bd78): perf score=1.000000
I20260812 06:17:25.125833  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: MajorDeltaCompactionOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.213s	user 0.115s	sys 0.084s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24692757,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1284,"lbm_read_time_us":14872,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34566,"lbm_writes_lt_1ms":543,"mutex_wait_us":382,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3456,"update_count":2500}
I20260812 06:17:25.126461  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78): perf score=14.095187
I20260812 06:17:25.193696  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.067s	user 0.049s	sys 0.008s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":25752,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:25.194469  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78): perf score=2.188937
I20260812 06:17:25.221937  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.027s	user 0.008s	sys 0.018s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6427,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:25.222681  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling FlushMRSOp(c74ae2da387b4e7ea9cd664670f5bd78): perf score=1.000000
I20260812 06:17:25.260751  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: FlushMRSOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.038s	user 0.036s	sys 0.000s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":106,"dirs.run_cpu_time_us":302,"dirs.run_wall_time_us":1831,"drs_written":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1749,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:25.261729  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling LogGCOp(c74ae2da387b4e7ea9cd664670f5bd78): free 119647519 bytes of WAL
I20260812 06:17:25.262027  1903 log_reader.cc:385] T c74ae2da387b4e7ea9cd664670f5bd78: removed 12 log segments from log reader
I20260812 06:17:25.262074  1903 log.cc:1079] T c74ae2da387b4e7ea9cd664670f5bd78 P c3d6d8e15a714a2f84729051e2c047c0: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/c74ae2da387b4e7ea9cd664670f5bd78/wal-000000027 (ops 129-132)
I20260812 06:17:25.262110  1903 log.cc:1079] T c74ae2da387b4e7ea9cd664670f5bd78 P c3d6d8e15a714a2f84729051e2c047c0: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/c74ae2da387b4e7ea9cd664670f5bd78/wal-000000028 (ops 133-137)
I20260812 06:17:25.262184  1903 log.cc:1079] T c74ae2da387b4e7ea9cd664670f5bd78 P c3d6d8e15a714a2f84729051e2c047c0: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/c74ae2da387b4e7ea9cd664670f5bd78/wal-000000029 (ops 138-142)
I20260812 06:17:25.262217  1903 log.cc:1079] T c74ae2da387b4e7ea9cd664670f5bd78 P c3d6d8e15a714a2f84729051e2c047c0: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/c74ae2da387b4e7ea9cd664670f5bd78/wal-000000030 (ops 143-147)
I20260812 06:17:25.262272  1903 log.cc:1079] T c74ae2da387b4e7ea9cd664670f5bd78 P c3d6d8e15a714a2f84729051e2c047c0: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/c74ae2da387b4e7ea9cd664670f5bd78/wal-000000031 (ops 148-152)
I20260812 06:17:25.262324  1903 log.cc:1079] T c74ae2da387b4e7ea9cd664670f5bd78 P c3d6d8e15a714a2f84729051e2c047c0: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/c74ae2da387b4e7ea9cd664670f5bd78/wal-000000032 (ops 153-156)
I20260812 06:17:25.262368  1903 log.cc:1079] T c74ae2da387b4e7ea9cd664670f5bd78 P c3d6d8e15a714a2f84729051e2c047c0: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/c74ae2da387b4e7ea9cd664670f5bd78/wal-000000033 (ops 157-161)
I20260812 06:17:25.262413  1903 log.cc:1079] T c74ae2da387b4e7ea9cd664670f5bd78 P c3d6d8e15a714a2f84729051e2c047c0: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/c74ae2da387b4e7ea9cd664670f5bd78/wal-000000034 (ops 162-166)
I20260812 06:17:25.262456  1903 log.cc:1079] T c74ae2da387b4e7ea9cd664670f5bd78 P c3d6d8e15a714a2f84729051e2c047c0: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/c74ae2da387b4e7ea9cd664670f5bd78/wal-000000035 (ops 167-170)
I20260812 06:17:25.262495  1903 log.cc:1079] T c74ae2da387b4e7ea9cd664670f5bd78 P c3d6d8e15a714a2f84729051e2c047c0: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/c74ae2da387b4e7ea9cd664670f5bd78/wal-000000036 (ops 171-175)
I20260812 06:17:25.262542  1903 log.cc:1079] T c74ae2da387b4e7ea9cd664670f5bd78 P c3d6d8e15a714a2f84729051e2c047c0: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/c74ae2da387b4e7ea9cd664670f5bd78/wal-000000037 (ops 176-180)
I20260812 06:17:25.262588  1903 log.cc:1079] T c74ae2da387b4e7ea9cd664670f5bd78 P c3d6d8e15a714a2f84729051e2c047c0: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/c74ae2da387b4e7ea9cd664670f5bd78/wal-000000038 (ops 181-184)
I20260812 06:17:25.294256  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: LogGCOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.032s	user 0.000s	sys 0.031s Metrics: {}
I20260812 06:17:25.294828  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling UndoDeltaBlockGCOp(c74ae2da387b4e7ea9cd664670f5bd78): 447 bytes on disk
I20260812 06:17:25.295513  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: UndoDeltaBlockGCOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":83,"lbm_reads_lt_1ms":4}
I20260812 06:17:25.296306  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78): perf score=3.181125
I20260812 06:17:25.312665  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.016s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4512904,"delete_count":0,"lbm_write_time_us":5109,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:25.313402  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78): perf score=2.188937
I20260812 06:17:25.324437  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3919,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:25.325299  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling MajorDeltaCompactionOp(c74ae2da387b4e7ea9cd664670f5bd78): perf score=1.000000
I20260812 06:17:25.587826  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: MajorDeltaCompactionOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.262s	user 0.188s	sys 0.072s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32897814,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":270,"lbm_read_time_us":18984,"lbm_reads_lt_1ms":774,"lbm_write_time_us":45649,"lbm_writes_lt_1ms":743,"mutex_wait_us":159,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":4224,"thread_start_us":110,"threads_started":1,"update_count":3500}
I20260812 06:17:25.588907  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78): perf score=16.079562
I20260812 06:17:25.648204  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.059s	user 0.034s	sys 0.022s Metrics: {"bytes_written":17886769,"delete_count":0,"lbm_write_time_us":27048,"lbm_writes_lt_1ms":439,"reinsert_count":0,"update_count":2180}
I20260812 06:17:25.648909  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78): perf score=1.196750
I20260812 06:17:25.675041  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.026s	user 0.006s	sys 0.005s Metrics: {"bytes_written":2625754,"delete_count":0,"lbm_write_time_us":4675,"lbm_writes_lt_1ms":67,"mutex_wait_us":36,"reinsert_count":0,"update_count":320}
I20260812 06:17:25.675616  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78): perf score=2.188937
I20260812 06:17:25.687572  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: FlushDeltaMemStoresOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4449,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:25.688184  1971 maintenance_manager.cc:419] P c3d6d8e15a714a2f84729051e2c047c0: Scheduling MajorDeltaCompactionOp(c74ae2da387b4e7ea9cd664670f5bd78): perf score=1.000000
I20260812 06:17:25.727388  1787 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.887s	user 2.059s	sys 0.205s
I20260812 06:17:25.822031  1787 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.094s	user 0.003s	sys 0.000s
I20260812 06:17:25.822826  1787 tablet_server.cc:179] TabletServer@127.1.190.193:0 shutting down...
I20260812 06:17:25.890954  1903 maintenance_manager.cc:643] P c3d6d8e15a714a2f84729051e2c047c0: MajorDeltaCompactionOp(c74ae2da387b4e7ea9cd664670f5bd78) complete. Timing: real 0.203s	user 0.131s	sys 0.071s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28795252,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":628,"lbm_read_time_us":16276,"lbm_reads_lt_1ms":669,"lbm_write_time_us":36356,"lbm_writes_lt_1ms":643,"mutex_wait_us":149,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":45824,"update_count":3000}
I20260812 06:17:25.892016  1787 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:25.892572  1787 tablet_replica.cc:333] T c74ae2da387b4e7ea9cd664670f5bd78 P c3d6d8e15a714a2f84729051e2c047c0: stopping tablet replica
I20260812 06:17:25.892938  1787 raft_consensus.cc:2243] T c74ae2da387b4e7ea9cd664670f5bd78 P c3d6d8e15a714a2f84729051e2c047c0 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:25.893280  1787 raft_consensus.cc:2272] T c74ae2da387b4e7ea9cd664670f5bd78 P c3d6d8e15a714a2f84729051e2c047c0 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:25.912220  1787 tablet_server.cc:196] TabletServer@127.1.190.193:0 shutdown complete.
I20260812 06:17:25.947360  1787 master.cc:562] Master@127.1.190.254:33465 shutting down...
I20260812 06:17:25.952711  1787 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 7a268c8a2d324753aa2e30dc60b2dad7 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:25.953059  1787 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 7a268c8a2d324753aa2e30dc60b2dad7 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:25.953176  1787 tablet_replica.cc:333] T 00000000000000000000000000000000 P 7a268c8a2d324753aa2e30dc60b2dad7: stopping tablet replica
I20260812 06:17:25.966579  1787 master.cc:584] Master@127.1.190.254:33465 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (6585 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:17:26.090776  1787 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.1.190.254:43855
I20260812 06:17:26.091316  1787 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:26.094908  2012 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:26.094920  2009 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:26.095357  2008 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:26.095988  1787 server_base.cc:1061] running on GCE node
I20260812 06:17:26.096207  1787 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:26.096246  1787 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:26.096263  1787 hybrid_clock.cc:648] HybridClock initialized: now 1786515446096263 us; error 0 us; skew 500 ppm
I20260812 06:17:26.097409  1787 webserver.cc:533] Webserver started at http://127.1.190.254:40071/ using document root <none> and password file <none>
I20260812 06:17:26.097595  1787 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:26.097652  1787 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:26.097747  1787 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:26.098188  1787 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439479178-1787-0/minicluster-data/master-0-root/instance:
uuid: "ae9afff54e6a4c8cbbe7e4e991b989f5"
format_stamp: "Formatted at 2026-08-12 06:17:26 on dist-test-slave-77v9"
I20260812 06:17:26.100242  1787 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.000s	sys 0.003s
I20260812 06:17:26.101704  2018 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:26.102288  1787 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:26.102470  1787 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439479178-1787-0/minicluster-data/master-0-root
uuid: "ae9afff54e6a4c8cbbe7e4e991b989f5"
format_stamp: "Formatted at 2026-08-12 06:17:26 on dist-test-slave-77v9"
I20260812 06:17:26.102581  1787 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439479178-1787-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439479178-1787-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439479178-1787-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:26.108608  1787 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:26.109154  1787 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:26.115662  1787 rpc_server.cc:307] RPC server started. Bound to: 127.1.190.254:43855
I20260812 06:17:26.118295  2078 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.1.190.254:43855 every 8 connection(s)
I20260812 06:17:26.119040  2080 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:26.122085  2080 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P ae9afff54e6a4c8cbbe7e4e991b989f5: Bootstrap starting.
I20260812 06:17:26.123200  2080 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P ae9afff54e6a4c8cbbe7e4e991b989f5: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:26.124579  2080 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P ae9afff54e6a4c8cbbe7e4e991b989f5: No bootstrap required, opened a new log
I20260812 06:17:26.125222  2080 raft_consensus.cc:359] T 00000000000000000000000000000000 P ae9afff54e6a4c8cbbe7e4e991b989f5 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ae9afff54e6a4c8cbbe7e4e991b989f5" member_type: VOTER }
I20260812 06:17:26.125367  2080 raft_consensus.cc:385] T 00000000000000000000000000000000 P ae9afff54e6a4c8cbbe7e4e991b989f5 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:26.125420  2080 raft_consensus.cc:740] T 00000000000000000000000000000000 P ae9afff54e6a4c8cbbe7e4e991b989f5 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: ae9afff54e6a4c8cbbe7e4e991b989f5, State: Initialized, Role: FOLLOWER
I20260812 06:17:26.125622  2080 consensus_queue.cc:260] T 00000000000000000000000000000000 P ae9afff54e6a4c8cbbe7e4e991b989f5 [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: "ae9afff54e6a4c8cbbe7e4e991b989f5" member_type: VOTER }
I20260812 06:17:26.125730  2080 raft_consensus.cc:399] T 00000000000000000000000000000000 P ae9afff54e6a4c8cbbe7e4e991b989f5 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:26.125787  2080 raft_consensus.cc:493] T 00000000000000000000000000000000 P ae9afff54e6a4c8cbbe7e4e991b989f5 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:26.125850  2080 raft_consensus.cc:3060] T 00000000000000000000000000000000 P ae9afff54e6a4c8cbbe7e4e991b989f5 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:26.126848  2080 raft_consensus.cc:515] T 00000000000000000000000000000000 P ae9afff54e6a4c8cbbe7e4e991b989f5 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ae9afff54e6a4c8cbbe7e4e991b989f5" member_type: VOTER }
I20260812 06:17:26.127071  2080 leader_election.cc:304] T 00000000000000000000000000000000 P ae9afff54e6a4c8cbbe7e4e991b989f5 [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: ae9afff54e6a4c8cbbe7e4e991b989f5; no voters: 
I20260812 06:17:26.127343  2080 leader_election.cc:290] T 00000000000000000000000000000000 P ae9afff54e6a4c8cbbe7e4e991b989f5 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:26.127552  2083 raft_consensus.cc:2804] T 00000000000000000000000000000000 P ae9afff54e6a4c8cbbe7e4e991b989f5 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:26.127803  2083 raft_consensus.cc:697] T 00000000000000000000000000000000 P ae9afff54e6a4c8cbbe7e4e991b989f5 [term 1 LEADER]: Becoming Leader. State: Replica: ae9afff54e6a4c8cbbe7e4e991b989f5, State: Running, Role: LEADER
I20260812 06:17:26.127976  2080 sys_catalog.cc:565] T 00000000000000000000000000000000 P ae9afff54e6a4c8cbbe7e4e991b989f5 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:26.128010  2083 consensus_queue.cc:237] T 00000000000000000000000000000000 P ae9afff54e6a4c8cbbe7e4e991b989f5 [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: "ae9afff54e6a4c8cbbe7e4e991b989f5" member_type: VOTER }
I20260812 06:17:26.128651  2085 sys_catalog.cc:455] T 00000000000000000000000000000000 P ae9afff54e6a4c8cbbe7e4e991b989f5 [sys.catalog]: SysCatalogTable state changed. Reason: New leader ae9afff54e6a4c8cbbe7e4e991b989f5. Latest consensus state: current_term: 1 leader_uuid: "ae9afff54e6a4c8cbbe7e4e991b989f5" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ae9afff54e6a4c8cbbe7e4e991b989f5" member_type: VOTER } }
I20260812 06:17:26.128834  2085 sys_catalog.cc:458] T 00000000000000000000000000000000 P ae9afff54e6a4c8cbbe7e4e991b989f5 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:26.128990  2084 sys_catalog.cc:455] T 00000000000000000000000000000000 P ae9afff54e6a4c8cbbe7e4e991b989f5 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "ae9afff54e6a4c8cbbe7e4e991b989f5" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ae9afff54e6a4c8cbbe7e4e991b989f5" member_type: VOTER } }
I20260812 06:17:26.129112  2084 sys_catalog.cc:458] T 00000000000000000000000000000000 P ae9afff54e6a4c8cbbe7e4e991b989f5 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:26.129547  2090 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:26.130738  2090 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:26.131139  1787 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:26.133426  2090 catalog_manager.cc:1383] Generated new cluster ID: 67972b2c5ee74c7abf72a6867f6bc786
I20260812 06:17:26.133528  2090 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:26.155827  2090 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:26.156546  2090 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:26.169620  2090 catalog_manager.cc:6092] T 00000000000000000000000000000000 P ae9afff54e6a4c8cbbe7e4e991b989f5: Generated new TSK 0
I20260812 06:17:26.169945  2090 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:26.197184  1787 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:26.200228  2108 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:26.200222  2110 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:26.200260  1787 server_base.cc:1061] running on GCE node
W20260812 06:17:26.200228  2107 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:26.201216  1787 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:26.201283  1787 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:26.201303  1787 hybrid_clock.cc:648] HybridClock initialized: now 1786515446201302 us; error 0 us; skew 500 ppm
I20260812 06:17:26.202399  1787 webserver.cc:533] Webserver started at http://127.1.190.193:42941/ using document root <none> and password file <none>
I20260812 06:17:26.202581  1787 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:26.202633  1787 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:26.202695  1787 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:26.203114  1787 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439479178-1787-0/minicluster-data/ts-0-root/instance:
uuid: "cd9ba7b944874ecbb2aa8b0c9b22eb03"
format_stamp: "Formatted at 2026-08-12 06:17:26 on dist-test-slave-77v9"
I20260812 06:17:26.205044  1787 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:26.206357  2117 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:26.206774  1787 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:26.206900  1787 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439479178-1787-0/minicluster-data/ts-0-root
uuid: "cd9ba7b944874ecbb2aa8b0c9b22eb03"
format_stamp: "Formatted at 2026-08-12 06:17:26 on dist-test-slave-77v9"
I20260812 06:17:26.207023  1787 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439479178-1787-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439479178-1787-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439479178-1787-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:26.226146  1787 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:26.226682  1787 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:26.227164  1787 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:26.227830  1787 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:26.227908  1787 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:26.228004  1787 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:26.228075  1787 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:26.234772  1787 rpc_server.cc:307] RPC server started. Bound to: 127.1.190.193:43587
I20260812 06:17:26.238212  2186 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.1.190.193:43587 every 8 connection(s)
I20260812 06:17:26.250597  2187 heartbeater.cc:344] Connected to a master server at 127.1.190.254:43855
I20260812 06:17:26.250833  2187 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:26.251214  2187 heartbeater.cc:507] Master 127.1.190.254:43855 requested a full tablet report, sending...
I20260812 06:17:26.252312  2038 ts_manager.cc:194] Registered new tserver with Master: cd9ba7b944874ecbb2aa8b0c9b22eb03 (127.1.190.193:43587)
I20260812 06:17:26.252791  1787 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.01688788s
I20260812 06:17:26.253707  2038 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:36314
I20260812 06:17:26.264478  2038 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:36322:
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:26.278029  2145 tablet_service.cc:1511] Processing CreateTablet for tablet fcf8fbbbc01344558cc7bca4b3636cc9 (DEFAULT_TABLE table=heavy-update-compaction-test [id=151b8028c17f4c0291e85f6592f3f8c3]), partition=
I20260812 06:17:26.278450  2145 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet fcf8fbbbc01344558cc7bca4b3636cc9. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:26.281404  2202 tablet_bootstrap.cc:492] T fcf8fbbbc01344558cc7bca4b3636cc9 P cd9ba7b944874ecbb2aa8b0c9b22eb03: Bootstrap starting.
I20260812 06:17:26.282574  2202 tablet_bootstrap.cc:654] T fcf8fbbbc01344558cc7bca4b3636cc9 P cd9ba7b944874ecbb2aa8b0c9b22eb03: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:26.284035  2202 tablet_bootstrap.cc:492] T fcf8fbbbc01344558cc7bca4b3636cc9 P cd9ba7b944874ecbb2aa8b0c9b22eb03: No bootstrap required, opened a new log
I20260812 06:17:26.284168  2202 ts_tablet_manager.cc:1403] T fcf8fbbbc01344558cc7bca4b3636cc9 P cd9ba7b944874ecbb2aa8b0c9b22eb03: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:17:26.284639  2202 raft_consensus.cc:359] T fcf8fbbbc01344558cc7bca4b3636cc9 P cd9ba7b944874ecbb2aa8b0c9b22eb03 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "cd9ba7b944874ecbb2aa8b0c9b22eb03" member_type: VOTER last_known_addr { host: "127.1.190.193" port: 43587 } }
I20260812 06:17:26.284754  2202 raft_consensus.cc:385] T fcf8fbbbc01344558cc7bca4b3636cc9 P cd9ba7b944874ecbb2aa8b0c9b22eb03 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:26.284780  2202 raft_consensus.cc:740] T fcf8fbbbc01344558cc7bca4b3636cc9 P cd9ba7b944874ecbb2aa8b0c9b22eb03 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: cd9ba7b944874ecbb2aa8b0c9b22eb03, State: Initialized, Role: FOLLOWER
I20260812 06:17:26.285019  2202 consensus_queue.cc:260] T fcf8fbbbc01344558cc7bca4b3636cc9 P cd9ba7b944874ecbb2aa8b0c9b22eb03 [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: "cd9ba7b944874ecbb2aa8b0c9b22eb03" member_type: VOTER last_known_addr { host: "127.1.190.193" port: 43587 } }
I20260812 06:17:26.285136  2202 raft_consensus.cc:399] T fcf8fbbbc01344558cc7bca4b3636cc9 P cd9ba7b944874ecbb2aa8b0c9b22eb03 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:26.285168  2202 raft_consensus.cc:493] T fcf8fbbbc01344558cc7bca4b3636cc9 P cd9ba7b944874ecbb2aa8b0c9b22eb03 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:26.285203  2202 raft_consensus.cc:3060] T fcf8fbbbc01344558cc7bca4b3636cc9 P cd9ba7b944874ecbb2aa8b0c9b22eb03 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:26.286145  2202 raft_consensus.cc:515] T fcf8fbbbc01344558cc7bca4b3636cc9 P cd9ba7b944874ecbb2aa8b0c9b22eb03 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "cd9ba7b944874ecbb2aa8b0c9b22eb03" member_type: VOTER last_known_addr { host: "127.1.190.193" port: 43587 } }
I20260812 06:17:26.286314  2202 leader_election.cc:304] T fcf8fbbbc01344558cc7bca4b3636cc9 P cd9ba7b944874ecbb2aa8b0c9b22eb03 [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: cd9ba7b944874ecbb2aa8b0c9b22eb03; no voters: 
I20260812 06:17:26.286551  2202 leader_election.cc:290] T fcf8fbbbc01344558cc7bca4b3636cc9 P cd9ba7b944874ecbb2aa8b0c9b22eb03 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:26.286798  2204 raft_consensus.cc:2804] T fcf8fbbbc01344558cc7bca4b3636cc9 P cd9ba7b944874ecbb2aa8b0c9b22eb03 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:26.286959  2204 raft_consensus.cc:697] T fcf8fbbbc01344558cc7bca4b3636cc9 P cd9ba7b944874ecbb2aa8b0c9b22eb03 [term 1 LEADER]: Becoming Leader. State: Replica: cd9ba7b944874ecbb2aa8b0c9b22eb03, State: Running, Role: LEADER
I20260812 06:17:26.287002  2202 ts_tablet_manager.cc:1434] T fcf8fbbbc01344558cc7bca4b3636cc9 P cd9ba7b944874ecbb2aa8b0c9b22eb03: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:17:26.287007  2187 heartbeater.cc:499] Master 127.1.190.254:43855 was elected leader, sending a full tablet report...
I20260812 06:17:26.287124  2204 consensus_queue.cc:237] T fcf8fbbbc01344558cc7bca4b3636cc9 P cd9ba7b944874ecbb2aa8b0c9b22eb03 [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: "cd9ba7b944874ecbb2aa8b0c9b22eb03" member_type: VOTER last_known_addr { host: "127.1.190.193" port: 43587 } }
I20260812 06:17:26.288980  2038 catalog_manager.cc:5719] T fcf8fbbbc01344558cc7bca4b3636cc9 P cd9ba7b944874ecbb2aa8b0c9b22eb03 reported cstate change: term changed from 0 to 1, leader changed from <none> to cd9ba7b944874ecbb2aa8b0c9b22eb03 (127.1.190.193). New cstate: current_term: 1 leader_uuid: "cd9ba7b944874ecbb2aa8b0c9b22eb03" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "cd9ba7b944874ecbb2aa8b0c9b22eb03" member_type: VOTER last_known_addr { host: "127.1.190.193" port: 43587 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:26.360589  1787 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.064s	user 0.016s	sys 0.011s
I20260812 06:17:26.488762  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling FlushMRSOp(fcf8fbbbc01344558cc7bca4b3636cc9): perf score=12.109628
I20260812 06:17:26.670149  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: FlushMRSOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.181s	user 0.139s	sys 0.037s Metrics: {"bytes_written":8615323,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":84,"dirs.run_cpu_time_us":251,"dirs.run_wall_time_us":1087,"drs_written":1,"lbm_read_time_us":69,"lbm_reads_lt_1ms":4,"lbm_write_time_us":41759,"lbm_writes_lt_1ms":567,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"spinlock_wait_cycles":1920,"update_count":1050}
I20260812 06:17:26.671236  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling LogGCOp(fcf8fbbbc01344558cc7bca4b3636cc9): free 20290830 bytes of WAL
I20260812 06:17:26.671690  2122 log_reader.cc:385] T fcf8fbbbc01344558cc7bca4b3636cc9: removed 2 log segments from log reader
I20260812 06:17:26.671788  2122 log.cc:1079] T fcf8fbbbc01344558cc7bca4b3636cc9 P cd9ba7b944874ecbb2aa8b0c9b22eb03: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/fcf8fbbbc01344558cc7bca4b3636cc9/wal-000000001 (ops 1-6)
I20260812 06:17:26.671855  2122 log.cc:1079] T fcf8fbbbc01344558cc7bca4b3636cc9 P cd9ba7b944874ecbb2aa8b0c9b22eb03: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/fcf8fbbbc01344558cc7bca4b3636cc9/wal-000000002 (ops 7-10)
I20260812 06:17:26.677260  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: LogGCOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.006s	user 0.000s	sys 0.005s Metrics: {}
I20260812 06:17:26.677932  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling UndoDeltaBlockGCOp(fcf8fbbbc01344558cc7bca4b3636cc9): 12308958 bytes on disk
I20260812 06:17:26.678591  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: UndoDeltaBlockGCOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":101,"lbm_reads_lt_1ms":4}
I20260812 06:17:26.679158  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9): perf score=2.188937
I20260812 06:17:26.693662  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.014s	user 0.009s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5028,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:26.695168  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling MajorDeltaCompactionOp(fcf8fbbbc01344558cc7bca4b3636cc9): perf score=1.000000
I20260812 06:17:26.852370  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: MajorDeltaCompactionOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.157s	user 0.103s	sys 0.052s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16528891,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":856,"lbm_read_time_us":12453,"lbm_reads_lt_1ms":368,"lbm_write_time_us":21464,"lbm_writes_lt_1ms":343,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":5504,"thread_start_us":432,"threads_started":5,"update_count":1500}
I20260812 06:17:26.853230  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9): perf score=10.126437
I20260812 06:17:26.904098  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.051s	user 0.028s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20016,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:26.904734  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9): perf score=2.188937
I20260812 06:17:26.921650  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.017s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5955,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:26.922669  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling MajorDeltaCompactionOp(fcf8fbbbc01344558cc7bca4b3636cc9): perf score=1.000000
I20260812 06:17:27.079838  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: MajorDeltaCompactionOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.157s	user 0.123s	sys 0.031s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":369,"lbm_read_time_us":9410,"lbm_reads_lt_1ms":472,"lbm_write_time_us":30396,"lbm_writes_lt_1ms":443,"mutex_wait_us":55,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11264,"update_count":2000}
I20260812 06:17:27.080681  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9): perf score=10.126437
I20260812 06:17:27.133225  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.052s	user 0.020s	sys 0.021s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18105,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:27.133901  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9): perf score=2.188937
I20260812 06:17:27.148362  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.014s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5493,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:27.149137  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling MajorDeltaCompactionOp(fcf8fbbbc01344558cc7bca4b3636cc9): perf score=1.000000
I20260812 06:17:27.291168  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: MajorDeltaCompactionOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.142s	user 0.104s	sys 0.037s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":754,"lbm_read_time_us":12230,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26873,"lbm_writes_lt_1ms":443,"mutex_wait_us":374,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":75904,"update_count":2000}
I20260812 06:17:27.294728  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9): perf score=10.126437
I20260812 06:17:27.349613  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.055s	user 0.021s	sys 0.031s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18933,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:27.350337  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9): perf score=2.188937
I20260812 06:17:27.362586  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.012s	user 0.002s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4943,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:27.363080  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling MajorDeltaCompactionOp(fcf8fbbbc01344558cc7bca4b3636cc9): perf score=1.000000
I20260812 06:17:27.555282  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: MajorDeltaCompactionOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.192s	user 0.125s	sys 0.067s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":278,"lbm_read_time_us":13749,"lbm_reads_lt_1ms":472,"lbm_write_time_us":34163,"lbm_writes_lt_1ms":443,"mutex_wait_us":101,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":18816,"update_count":2000}
I20260812 06:17:27.559448  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9): perf score=10.126437
I20260812 06:17:27.609920  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.050s	user 0.031s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18864,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:27.610980  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9): perf score=2.188937
I20260812 06:17:27.625521  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.014s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5429,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:27.626252  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling MajorDeltaCompactionOp(fcf8fbbbc01344558cc7bca4b3636cc9): perf score=1.000000
I20260812 06:17:27.785080  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: MajorDeltaCompactionOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.159s	user 0.106s	sys 0.052s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":654,"lbm_read_time_us":10978,"lbm_reads_lt_1ms":472,"lbm_write_time_us":30340,"lbm_writes_lt_1ms":443,"mutex_wait_us":55,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3072,"update_count":2000}
I20260812 06:17:27.787391  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9): perf score=10.126437
I20260812 06:17:27.842252  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.055s	user 0.021s	sys 0.027s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":22046,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:27.843021  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9): perf score=2.188937
I20260812 06:17:27.858575  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.015s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6116,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:27.859182  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling MajorDeltaCompactionOp(fcf8fbbbc01344558cc7bca4b3636cc9): perf score=1.000000
I20260812 06:17:28.008271  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: MajorDeltaCompactionOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.149s	user 0.113s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":199,"lbm_read_time_us":11976,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27658,"lbm_writes_lt_1ms":443,"mutex_wait_us":62,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3200,"update_count":2000}
I20260812 06:17:28.009073  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9): perf score=10.126437
I20260812 06:17:28.052037  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.043s	user 0.025s	sys 0.013s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17692,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:28.052639  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9): perf score=2.188937
I20260812 06:17:28.064477  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.012s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4693,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:28.065119  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling MajorDeltaCompactionOp(fcf8fbbbc01344558cc7bca4b3636cc9): perf score=1.000000
I20260812 06:17:28.211155  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: MajorDeltaCompactionOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.146s	user 0.117s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":944,"lbm_read_time_us":10342,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27420,"lbm_writes_lt_1ms":443,"mutex_wait_us":407,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12160,"update_count":2000}
I20260812 06:17:28.212016  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9): perf score=10.126437
I20260812 06:17:28.273437  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.061s	user 0.029s	sys 0.027s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20835,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:28.274168  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9): perf score=2.188937
I20260812 06:17:28.287813  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5238,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:28.288451  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling FlushMRSOp(fcf8fbbbc01344558cc7bca4b3636cc9): perf score=1.000000
I20260812 06:17:28.339821  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: FlushMRSOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.051s	user 0.036s	sys 0.000s Metrics: {"bytes_written":1275444,"cfile_init":1,"dirs.queue_time_us":132,"dirs.run_cpu_time_us":272,"dirs.run_wall_time_us":2159,"drs_written":1,"lbm_read_time_us":77,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2356,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:28.340575  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling LogGCOp(fcf8fbbbc01344558cc7bca4b3636cc9): free 120553374 bytes of WAL
I20260812 06:17:28.340955  2122 log_reader.cc:385] T fcf8fbbbc01344558cc7bca4b3636cc9: removed 12 log segments from log reader
I20260812 06:17:28.341003  2122 log.cc:1079] T fcf8fbbbc01344558cc7bca4b3636cc9 P cd9ba7b944874ecbb2aa8b0c9b22eb03: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/fcf8fbbbc01344558cc7bca4b3636cc9/wal-000000003 (ops 11-15)
I20260812 06:17:28.341035  2122 log.cc:1079] T fcf8fbbbc01344558cc7bca4b3636cc9 P cd9ba7b944874ecbb2aa8b0c9b22eb03: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/fcf8fbbbc01344558cc7bca4b3636cc9/wal-000000004 (ops 16-20)
I20260812 06:17:28.341099  2122 log.cc:1079] T fcf8fbbbc01344558cc7bca4b3636cc9 P cd9ba7b944874ecbb2aa8b0c9b22eb03: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/fcf8fbbbc01344558cc7bca4b3636cc9/wal-000000005 (ops 21-25)
I20260812 06:17:28.341145  2122 log.cc:1079] T fcf8fbbbc01344558cc7bca4b3636cc9 P cd9ba7b944874ecbb2aa8b0c9b22eb03: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/fcf8fbbbc01344558cc7bca4b3636cc9/wal-000000006 (ops 26-30)
I20260812 06:17:28.341192  2122 log.cc:1079] T fcf8fbbbc01344558cc7bca4b3636cc9 P cd9ba7b944874ecbb2aa8b0c9b22eb03: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/fcf8fbbbc01344558cc7bca4b3636cc9/wal-000000007 (ops 31-34)
I20260812 06:17:28.341253  2122 log.cc:1079] T fcf8fbbbc01344558cc7bca4b3636cc9 P cd9ba7b944874ecbb2aa8b0c9b22eb03: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/fcf8fbbbc01344558cc7bca4b3636cc9/wal-000000008 (ops 35-39)
I20260812 06:17:28.341284  2122 log.cc:1079] T fcf8fbbbc01344558cc7bca4b3636cc9 P cd9ba7b944874ecbb2aa8b0c9b22eb03: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/fcf8fbbbc01344558cc7bca4b3636cc9/wal-000000009 (ops 40-44)
I20260812 06:17:28.341339  2122 log.cc:1079] T fcf8fbbbc01344558cc7bca4b3636cc9 P cd9ba7b944874ecbb2aa8b0c9b22eb03: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/fcf8fbbbc01344558cc7bca4b3636cc9/wal-000000010 (ops 45-49)
I20260812 06:17:28.341387  2122 log.cc:1079] T fcf8fbbbc01344558cc7bca4b3636cc9 P cd9ba7b944874ecbb2aa8b0c9b22eb03: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/fcf8fbbbc01344558cc7bca4b3636cc9/wal-000000011 (ops 50-54)
I20260812 06:17:28.341430  2122 log.cc:1079] T fcf8fbbbc01344558cc7bca4b3636cc9 P cd9ba7b944874ecbb2aa8b0c9b22eb03: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/fcf8fbbbc01344558cc7bca4b3636cc9/wal-000000012 (ops 55-58)
I20260812 06:17:28.341471  2122 log.cc:1079] T fcf8fbbbc01344558cc7bca4b3636cc9 P cd9ba7b944874ecbb2aa8b0c9b22eb03: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/fcf8fbbbc01344558cc7bca4b3636cc9/wal-000000013 (ops 59-63)
I20260812 06:17:28.341511  2122 log.cc:1079] T fcf8fbbbc01344558cc7bca4b3636cc9 P cd9ba7b944874ecbb2aa8b0c9b22eb03: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/fcf8fbbbc01344558cc7bca4b3636cc9/wal-000000014 (ops 64-68)
I20260812 06:17:28.374261  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: LogGCOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.033s	user 0.002s	sys 0.030s Metrics: {}
I20260812 06:17:28.374990  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling UndoDeltaBlockGCOp(fcf8fbbbc01344558cc7bca4b3636cc9): 482 bytes on disk
I20260812 06:17:28.375564  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: UndoDeltaBlockGCOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":92,"lbm_reads_lt_1ms":4}
I20260812 06:17:28.376293  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9): perf score=2.188937
I20260812 06:17:28.402191  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.026s	user 0.013s	sys 0.005s Metrics: {"bytes_written":4184708,"delete_count":0,"lbm_write_time_us":7507,"lbm_writes_lt_1ms":105,"reinsert_count":0,"update_count":510}
I20260812 06:17:28.402982  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9): perf score=2.188937
I20260812 06:17:28.417776  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.015s	user 0.009s	sys 0.005s Metrics: {"bytes_written":4020609,"delete_count":0,"lbm_write_time_us":5118,"lbm_writes_lt_1ms":101,"reinsert_count":0,"update_count":490}
I20260812 06:17:28.418970  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling MajorDeltaCompactionOp(fcf8fbbbc01344558cc7bca4b3636cc9): perf score=1.000000
I20260812 06:17:28.675369  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: MajorDeltaCompactionOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.256s	user 0.163s	sys 0.091s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836373,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":951,"lbm_read_time_us":18557,"lbm_reads_lt_1ms":674,"lbm_write_time_us":41607,"lbm_writes_lt_1ms":643,"mutex_wait_us":478,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":16256,"thread_start_us":99,"threads_started":1,"update_count":3000}
I20260812 06:17:28.676923  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9): perf score=14.095187
I20260812 06:17:28.745561  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.068s	user 0.043s	sys 0.020s Metrics: {"bytes_written":16409899,"delete_count":0,"lbm_write_time_us":28543,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:28.746296  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling MajorDeltaCompactionOp(fcf8fbbbc01344558cc7bca4b3636cc9): perf score=1.000000
I20260812 06:17:28.939225  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: MajorDeltaCompactionOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.193s	user 0.132s	sys 0.052s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20631190,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":526,"lbm_read_time_us":12904,"lbm_reads_lt_1ms":463,"lbm_write_time_us":29283,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4608,"update_count":2000}
I20260812 06:17:28.940040  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9): perf score=14.095187
I20260812 06:17:29.016547  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.076s	user 0.049s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":32334,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:29.017231  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9): perf score=2.188937
I20260812 06:17:29.032934  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.015s	user 0.012s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5194,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:29.033713  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling MajorDeltaCompactionOp(fcf8fbbbc01344558cc7bca4b3636cc9): perf score=1.000000
I20260812 06:17:29.254277  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: MajorDeltaCompactionOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.220s	user 0.153s	sys 0.061s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":612,"lbm_read_time_us":13819,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34818,"lbm_writes_lt_1ms":543,"mutex_wait_us":72,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10880,"update_count":2500}
I20260812 06:17:29.255610  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9): perf score=14.095187
I20260812 06:17:29.334355  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.078s	user 0.045s	sys 0.031s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":33038,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:17:29.335269  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9): perf score=2.188937
I20260812 06:17:29.355664  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.020s	user 0.006s	sys 0.013s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7678,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:29.356626  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling MajorDeltaCompactionOp(fcf8fbbbc01344558cc7bca4b3636cc9): perf score=1.000000
I20260812 06:17:29.558802  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: MajorDeltaCompactionOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.202s	user 0.166s	sys 0.029s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":246,"lbm_read_time_us":12608,"lbm_reads_lt_1ms":572,"lbm_write_time_us":41531,"lbm_writes_lt_1ms":543,"mutex_wait_us":302,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":41088,"update_count":2500}
I20260812 06:17:29.559533  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9): perf score=11.118625
I20260812 06:17:29.596419  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.037s	user 0.013s	sys 0.020s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":15632,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:29.597362  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9): perf score=2.188937
I20260812 06:17:29.615808  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.018s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5036,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:29.616542  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling MajorDeltaCompactionOp(fcf8fbbbc01344558cc7bca4b3636cc9): perf score=1.000000
I20260812 06:17:29.758272  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: MajorDeltaCompactionOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.141s	user 0.106s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631305,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":545,"lbm_read_time_us":8575,"lbm_reads_lt_1ms":464,"lbm_write_time_us":28800,"lbm_writes_lt_1ms":443,"mutex_wait_us":121,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:17:29.759096  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9): perf score=10.126437
I20260812 06:17:29.799047  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.040s	user 0.028s	sys 0.005s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15936,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:29.799690  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling MajorDeltaCompactionOp(fcf8fbbbc01344558cc7bca4b3636cc9): perf score=1.000000
I20260812 06:17:29.919106  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: MajorDeltaCompactionOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.119s	user 0.083s	sys 0.035s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16528780,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":518,"lbm_read_time_us":8256,"lbm_reads_lt_1ms":363,"lbm_write_time_us":21463,"lbm_writes_lt_1ms":343,"mutex_wait_us":173,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":11520,"update_count":1500}
I20260812 06:17:29.919778  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9): perf score=10.126437
I20260812 06:17:29.967125  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.047s	user 0.024s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16834,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:29.967810  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9): perf score=2.188937
I20260812 06:17:29.982694  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5179,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:29.983392  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling MajorDeltaCompactionOp(fcf8fbbbc01344558cc7bca4b3636cc9): perf score=1.000000
I20260812 06:17:30.126441  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: MajorDeltaCompactionOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.143s	user 0.111s	sys 0.031s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":283,"lbm_read_time_us":9497,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27193,"lbm_writes_lt_1ms":443,"mutex_wait_us":64,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:17:30.127192  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9): perf score=10.126437
I20260812 06:17:30.175683  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.048s	user 0.028s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20990,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:30.176270  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9): perf score=2.188937
I20260812 06:17:30.189129  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.013s	user 0.005s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4495,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:30.190445  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling FlushMRSOp(fcf8fbbbc01344558cc7bca4b3636cc9): perf score=1.000000
I20260812 06:17:30.228250  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: FlushMRSOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.037s	user 0.036s	sys 0.000s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":57,"dirs.run_cpu_time_us":279,"dirs.run_wall_time_us":1818,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2206,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:30.229180  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling LogGCOp(fcf8fbbbc01344558cc7bca4b3636cc9): free 129320465 bytes of WAL
I20260812 06:17:30.229457  2122 log_reader.cc:385] T fcf8fbbbc01344558cc7bca4b3636cc9: removed 13 log segments from log reader
I20260812 06:17:30.229503  2122 log.cc:1079] T fcf8fbbbc01344558cc7bca4b3636cc9 P cd9ba7b944874ecbb2aa8b0c9b22eb03: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/fcf8fbbbc01344558cc7bca4b3636cc9/wal-000000015 (ops 69-73)
I20260812 06:17:30.229535  2122 log.cc:1079] T fcf8fbbbc01344558cc7bca4b3636cc9 P cd9ba7b944874ecbb2aa8b0c9b22eb03: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/fcf8fbbbc01344558cc7bca4b3636cc9/wal-000000016 (ops 74-78)
I20260812 06:17:30.229607  2122 log.cc:1079] T fcf8fbbbc01344558cc7bca4b3636cc9 P cd9ba7b944874ecbb2aa8b0c9b22eb03: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/fcf8fbbbc01344558cc7bca4b3636cc9/wal-000000017 (ops 79-83)
I20260812 06:17:30.229657  2122 log.cc:1079] T fcf8fbbbc01344558cc7bca4b3636cc9 P cd9ba7b944874ecbb2aa8b0c9b22eb03: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/fcf8fbbbc01344558cc7bca4b3636cc9/wal-000000018 (ops 84-88)
I20260812 06:17:30.229703  2122 log.cc:1079] T fcf8fbbbc01344558cc7bca4b3636cc9 P cd9ba7b944874ecbb2aa8b0c9b22eb03: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/fcf8fbbbc01344558cc7bca4b3636cc9/wal-000000019 (ops 89-93)
I20260812 06:17:30.229756  2122 log.cc:1079] T fcf8fbbbc01344558cc7bca4b3636cc9 P cd9ba7b944874ecbb2aa8b0c9b22eb03: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/fcf8fbbbc01344558cc7bca4b3636cc9/wal-000000020 (ops 94-98)
I20260812 06:17:30.229801  2122 log.cc:1079] T fcf8fbbbc01344558cc7bca4b3636cc9 P cd9ba7b944874ecbb2aa8b0c9b22eb03: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/fcf8fbbbc01344558cc7bca4b3636cc9/wal-000000021 (ops 99-103)
I20260812 06:17:30.229861  2122 log.cc:1079] T fcf8fbbbc01344558cc7bca4b3636cc9 P cd9ba7b944874ecbb2aa8b0c9b22eb03: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/fcf8fbbbc01344558cc7bca4b3636cc9/wal-000000022 (ops 104-108)
I20260812 06:17:30.229902  2122 log.cc:1079] T fcf8fbbbc01344558cc7bca4b3636cc9 P cd9ba7b944874ecbb2aa8b0c9b22eb03: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/fcf8fbbbc01344558cc7bca4b3636cc9/wal-000000023 (ops 109-112)
I20260812 06:17:30.229943  2122 log.cc:1079] T fcf8fbbbc01344558cc7bca4b3636cc9 P cd9ba7b944874ecbb2aa8b0c9b22eb03: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/fcf8fbbbc01344558cc7bca4b3636cc9/wal-000000024 (ops 113-117)
I20260812 06:17:30.229982  2122 log.cc:1079] T fcf8fbbbc01344558cc7bca4b3636cc9 P cd9ba7b944874ecbb2aa8b0c9b22eb03: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/fcf8fbbbc01344558cc7bca4b3636cc9/wal-000000025 (ops 118-122)
I20260812 06:17:30.230027  2122 log.cc:1079] T fcf8fbbbc01344558cc7bca4b3636cc9 P cd9ba7b944874ecbb2aa8b0c9b22eb03: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/fcf8fbbbc01344558cc7bca4b3636cc9/wal-000000026 (ops 123-126)
I20260812 06:17:30.230070  2122 log.cc:1079] T fcf8fbbbc01344558cc7bca4b3636cc9 P cd9ba7b944874ecbb2aa8b0c9b22eb03: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/fcf8fbbbc01344558cc7bca4b3636cc9/wal-000000027 (ops 127-131)
I20260812 06:17:30.261200  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: LogGCOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.032s	user 0.000s	sys 0.032s Metrics: {}
I20260812 06:17:30.261781  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9): perf score=3.181125
I20260812 06:17:30.283821  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.022s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4389831,"delete_count":0,"lbm_write_time_us":8077,"lbm_writes_lt_1ms":110,"reinsert_count":0,"update_count":535}
I20260812 06:17:30.284344  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling UndoDeltaBlockGCOp(fcf8fbbbc01344558cc7bca4b3636cc9): 483 bytes on disk
I20260812 06:17:30.284834  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: UndoDeltaBlockGCOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":65,"lbm_reads_lt_1ms":4}
I20260812 06:17:30.285429  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9): perf score=2.188937
I20260812 06:17:30.296900  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.011s	user 0.009s	sys 0.003s Metrics: {"bytes_written":3815483,"delete_count":0,"lbm_write_time_us":4084,"lbm_writes_lt_1ms":96,"reinsert_count":0,"update_count":465}
I20260812 06:17:30.297839  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling MajorDeltaCompactionOp(fcf8fbbbc01344558cc7bca4b3636cc9): perf score=1.000000
I20260812 06:17:30.504084  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: MajorDeltaCompactionOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.206s	user 0.155s	sys 0.045s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836370,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":243,"lbm_read_time_us":16259,"lbm_reads_lt_1ms":674,"lbm_write_time_us":42424,"lbm_writes_lt_1ms":643,"mutex_wait_us":27,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":83712,"thread_start_us":90,"threads_started":1,"update_count":3000}
I20260812 06:17:30.504654  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9): perf score=14.095187
I20260812 06:17:30.566901  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.062s	user 0.033s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21188,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:30.567562  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9): perf score=2.188937
I20260812 06:17:30.584030  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.016s	user 0.003s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6706,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:30.584604  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling MajorDeltaCompactionOp(fcf8fbbbc01344558cc7bca4b3636cc9): perf score=1.000000
I20260812 06:17:30.783551  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: MajorDeltaCompactionOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.199s	user 0.137s	sys 0.051s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":285,"lbm_read_time_us":14332,"lbm_reads_lt_1ms":572,"lbm_write_time_us":36919,"lbm_writes_lt_1ms":543,"mutex_wait_us":33,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":27264,"update_count":2500}
I20260812 06:17:30.784371  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9): perf score=14.095187
I20260812 06:17:30.847452  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.063s	user 0.040s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25072,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:30.848121  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9): perf score=2.188937
I20260812 06:17:30.864177  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.016s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6469,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:30.864753  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling MajorDeltaCompactionOp(fcf8fbbbc01344558cc7bca4b3636cc9): perf score=1.000000
I20260812 06:17:31.057893  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: MajorDeltaCompactionOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.193s	user 0.149s	sys 0.037s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":319,"lbm_read_time_us":13440,"lbm_reads_lt_1ms":572,"lbm_write_time_us":39888,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":226944,"update_count":2500}
I20260812 06:17:31.058739  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9): perf score=14.095187
I20260812 06:17:31.123100  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.064s	user 0.036s	sys 0.021s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":26767,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:31.123844  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9): perf score=2.188937
I20260812 06:17:31.137916  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.014s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5090,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:31.138794  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling MajorDeltaCompactionOp(fcf8fbbbc01344558cc7bca4b3636cc9): perf score=1.000000
I20260812 06:17:31.324668  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: MajorDeltaCompactionOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.186s	user 0.137s	sys 0.035s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733722,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":129,"lbm_read_time_us":12401,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34548,"lbm_writes_lt_1ms":543,"mutex_wait_us":82,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":25088,"update_count":2500}
I20260812 06:17:31.325583  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9): perf score=14.095187
I20260812 06:17:31.397048  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.071s	user 0.035s	sys 0.023s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":26143,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:31.398160  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9): perf score=2.188937
I20260812 06:17:31.415546  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.017s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5956,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:31.416453  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling MajorDeltaCompactionOp(fcf8fbbbc01344558cc7bca4b3636cc9): perf score=1.000000
I20260812 06:17:31.633847  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: MajorDeltaCompactionOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.217s	user 0.122s	sys 0.093s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733722,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":285,"lbm_read_time_us":16386,"lbm_reads_lt_1ms":572,"lbm_write_time_us":37759,"lbm_writes_lt_1ms":543,"mutex_wait_us":68,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":27392,"update_count":2500}
I20260812 06:17:31.634575  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9): perf score=14.095187
I20260812 06:17:31.693270  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.058s	user 0.037s	sys 0.021s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":26375,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:31.693957  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling MajorDeltaCompactionOp(fcf8fbbbc01344558cc7bca4b3636cc9): perf score=1.000000
I20260812 06:17:31.863981  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: MajorDeltaCompactionOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.170s	user 0.137s	sys 0.033s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20631195,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":490,"lbm_read_time_us":11541,"lbm_reads_lt_1ms":463,"lbm_write_time_us":29011,"lbm_writes_lt_1ms":443,"mutex_wait_us":37,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:31.864729  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9): perf score=14.095187
I20260812 06:17:31.938248  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.073s	user 0.039s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":28365,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:31.939085  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9): perf score=2.188937
I20260812 06:17:31.958195  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.019s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":7168,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:31.959126  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling FlushMRSOp(fcf8fbbbc01344558cc7bca4b3636cc9): perf score=1.000000
I20260812 06:17:32.008198  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: FlushMRSOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.048s	user 0.035s	sys 0.001s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":115,"dirs.run_cpu_time_us":315,"dirs.run_wall_time_us":2026,"drs_written":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1959,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:32.009529  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling LogGCOp(fcf8fbbbc01344558cc7bca4b3636cc9): free 133024653 bytes of WAL
I20260812 06:17:32.009867  2122 log_reader.cc:385] T fcf8fbbbc01344558cc7bca4b3636cc9: removed 13 log segments from log reader
I20260812 06:17:32.009914  2122 log.cc:1079] T fcf8fbbbc01344558cc7bca4b3636cc9 P cd9ba7b944874ecbb2aa8b0c9b22eb03: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/fcf8fbbbc01344558cc7bca4b3636cc9/wal-000000028 (ops 132-136)
I20260812 06:17:32.009955  2122 log.cc:1079] T fcf8fbbbc01344558cc7bca4b3636cc9 P cd9ba7b944874ecbb2aa8b0c9b22eb03: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/fcf8fbbbc01344558cc7bca4b3636cc9/wal-000000029 (ops 137-141)
I20260812 06:17:32.010035  2122 log.cc:1079] T fcf8fbbbc01344558cc7bca4b3636cc9 P cd9ba7b944874ecbb2aa8b0c9b22eb03: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/fcf8fbbbc01344558cc7bca4b3636cc9/wal-000000030 (ops 142-146)
I20260812 06:17:32.010104  2122 log.cc:1079] T fcf8fbbbc01344558cc7bca4b3636cc9 P cd9ba7b944874ecbb2aa8b0c9b22eb03: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/fcf8fbbbc01344558cc7bca4b3636cc9/wal-000000031 (ops 147-151)
I20260812 06:17:32.010155  2122 log.cc:1079] T fcf8fbbbc01344558cc7bca4b3636cc9 P cd9ba7b944874ecbb2aa8b0c9b22eb03: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/fcf8fbbbc01344558cc7bca4b3636cc9/wal-000000032 (ops 152-156)
I20260812 06:17:32.010213  2122 log.cc:1079] T fcf8fbbbc01344558cc7bca4b3636cc9 P cd9ba7b944874ecbb2aa8b0c9b22eb03: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/fcf8fbbbc01344558cc7bca4b3636cc9/wal-000000033 (ops 157-161)
I20260812 06:17:32.010265  2122 log.cc:1079] T fcf8fbbbc01344558cc7bca4b3636cc9 P cd9ba7b944874ecbb2aa8b0c9b22eb03: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/fcf8fbbbc01344558cc7bca4b3636cc9/wal-000000034 (ops 162-166)
I20260812 06:17:32.010309  2122 log.cc:1079] T fcf8fbbbc01344558cc7bca4b3636cc9 P cd9ba7b944874ecbb2aa8b0c9b22eb03: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/fcf8fbbbc01344558cc7bca4b3636cc9/wal-000000035 (ops 167-171)
I20260812 06:17:32.010349  2122 log.cc:1079] T fcf8fbbbc01344558cc7bca4b3636cc9 P cd9ba7b944874ecbb2aa8b0c9b22eb03: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/fcf8fbbbc01344558cc7bca4b3636cc9/wal-000000036 (ops 172-176)
I20260812 06:17:32.010386  2122 log.cc:1079] T fcf8fbbbc01344558cc7bca4b3636cc9 P cd9ba7b944874ecbb2aa8b0c9b22eb03: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/fcf8fbbbc01344558cc7bca4b3636cc9/wal-000000037 (ops 177-181)
I20260812 06:17:32.010428  2122 log.cc:1079] T fcf8fbbbc01344558cc7bca4b3636cc9 P cd9ba7b944874ecbb2aa8b0c9b22eb03: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/fcf8fbbbc01344558cc7bca4b3636cc9/wal-000000038 (ops 182-186)
I20260812 06:17:32.010468  2122 log.cc:1079] T fcf8fbbbc01344558cc7bca4b3636cc9 P cd9ba7b944874ecbb2aa8b0c9b22eb03: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/fcf8fbbbc01344558cc7bca4b3636cc9/wal-000000039 (ops 187-190)
I20260812 06:17:32.010511  2122 log.cc:1079] T fcf8fbbbc01344558cc7bca4b3636cc9 P cd9ba7b944874ecbb2aa8b0c9b22eb03: Deleting log segment in path: /tmp/dist-test-taskC_yDiH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439479178-1787-0/minicluster-data/ts-0-root/wals/fcf8fbbbc01344558cc7bca4b3636cc9/wal-000000040 (ops 191-195)
I20260812 06:17:32.046103  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: LogGCOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.036s	user 0.007s	sys 0.028s Metrics: {}
I20260812 06:17:32.046674  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9): perf score=3.181125
I20260812 06:17:32.065359  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.018s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":5430,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:32.066005  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9): perf score=2.188937
I20260812 06:17:32.080129  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: FlushDeltaMemStoresOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.014s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4551,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:32.081125  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling UndoDeltaBlockGCOp(fcf8fbbbc01344558cc7bca4b3636cc9): 483 bytes on disk
I20260812 06:17:32.082252  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: UndoDeltaBlockGCOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":160,"lbm_reads_lt_1ms":4}
I20260812 06:17:32.083271  2188 maintenance_manager.cc:419] P cd9ba7b944874ecbb2aa8b0c9b22eb03: Scheduling MajorDeltaCompactionOp(fcf8fbbbc01344558cc7bca4b3636cc9): perf score=1.000000
I20260812 06:17:32.181756  1787 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.821s	user 2.109s	sys 0.179s
I20260812 06:17:32.305326  1787 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.123s	user 0.003s	sys 0.000s
I20260812 06:17:32.305915  1787 tablet_server.cc:179] TabletServer@127.1.190.193:0 shutting down...
I20260812 06:17:32.330082  2122 maintenance_manager.cc:643] P cd9ba7b944874ecbb2aa8b0c9b22eb03: MajorDeltaCompactionOp(fcf8fbbbc01344558cc7bca4b3636cc9) complete. Timing: real 0.247s	user 0.158s	sys 0.088s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32938774,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":817,"lbm_read_time_us":20411,"lbm_reads_lt_1ms":770,"lbm_write_time_us":40363,"lbm_writes_lt_1ms":743,"mutex_wait_us":24,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":35328,"thread_start_us":108,"threads_started":1,"update_count":3500}
I20260812 06:17:32.331132  1787 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:32.331629  1787 tablet_replica.cc:333] T fcf8fbbbc01344558cc7bca4b3636cc9 P cd9ba7b944874ecbb2aa8b0c9b22eb03: stopping tablet replica
I20260812 06:17:32.331835  1787 raft_consensus.cc:2243] T fcf8fbbbc01344558cc7bca4b3636cc9 P cd9ba7b944874ecbb2aa8b0c9b22eb03 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:32.332056  1787 raft_consensus.cc:2272] T fcf8fbbbc01344558cc7bca4b3636cc9 P cd9ba7b944874ecbb2aa8b0c9b22eb03 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:32.366403  1787 tablet_server.cc:196] TabletServer@127.1.190.193:0 shutdown complete.
I20260812 06:17:32.390082  1787 master.cc:562] Master@127.1.190.254:43855 shutting down...
I20260812 06:17:32.397054  1787 raft_consensus.cc:2243] T 00000000000000000000000000000000 P ae9afff54e6a4c8cbbe7e4e991b989f5 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:32.397570  1787 raft_consensus.cc:2272] T 00000000000000000000000000000000 P ae9afff54e6a4c8cbbe7e4e991b989f5 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:32.397691  1787 tablet_replica.cc:333] T 00000000000000000000000000000000 P ae9afff54e6a4c8cbbe7e4e991b989f5: stopping tablet replica
I20260812 06:17:32.411290  1787 master.cc:584] Master@127.1.190.254:43855 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (6436 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (13022 ms total)

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