[==========] 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:19:51.170070 29244 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.28.143.62:45309
I20260812 06:19:51.171034 29244 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:19:51.171590 29244 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:51.177500 29254 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:19:51.177500 29255 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:19:51.177677 29244 server_base.cc:1061] running on GCE node
W20260812 06:19:51.177779 29261 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:19:51.178180 29244 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:51.178275 29244 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:19:51.178318 29244 hybrid_clock.cc:648] HybridClock initialized: now 1786515591178316 us; error 0 us; skew 500 ppm
I20260812 06:19:51.179932 29244 webserver.cc:533] Webserver started at http://127.28.143.62:44559/ using document root <none> and password file <none>
I20260812 06:19:51.180420 29244 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:51.180485 29244 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:51.180688 29244 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:51.182252 29244 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591159890-29244-0/minicluster-data/master-0-root/instance:
uuid: "b9f13aefe0e2484aa568c014f8a35773"
format_stamp: "Formatted at 2026-08-12 06:19:51 on dist-test-slave-6zbq"
I20260812 06:19:51.185426 29244 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.002s	sys 0.001s
I20260812 06:19:51.187309 29268 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:19:51.188187 29244 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:19:51.188290 29244 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591159890-29244-0/minicluster-data/master-0-root
uuid: "b9f13aefe0e2484aa568c014f8a35773"
format_stamp: "Formatted at 2026-08-12 06:19:51 on dist-test-slave-6zbq"
I20260812 06:19:51.188371 29244 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591159890-29244-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591159890-29244-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591159890-29244-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:19:51.206235 29244 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:51.206840 29244 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:19:51.206983 29244 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:51.213971 29244 rpc_server.cc:307] RPC server started. Bound to: 127.28.143.62:45309
I20260812 06:19:51.213977 29364 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.28.143.62:45309 every 8 connection(s)
I20260812 06:19:51.216008 29367 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:19:51.220978 29367 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P b9f13aefe0e2484aa568c014f8a35773: Bootstrap starting.
I20260812 06:19:51.223220 29367 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P b9f13aefe0e2484aa568c014f8a35773: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:51.224012 29367 log.cc:826] T 00000000000000000000000000000000 P b9f13aefe0e2484aa568c014f8a35773: Log is configured to *not* fsync() on all Append() calls
I20260812 06:19:51.225449 29367 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P b9f13aefe0e2484aa568c014f8a35773: No bootstrap required, opened a new log
I20260812 06:19:51.227945 29367 raft_consensus.cc:359] T 00000000000000000000000000000000 P b9f13aefe0e2484aa568c014f8a35773 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b9f13aefe0e2484aa568c014f8a35773" member_type: VOTER }
I20260812 06:19:51.228092 29367 raft_consensus.cc:385] T 00000000000000000000000000000000 P b9f13aefe0e2484aa568c014f8a35773 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:51.228134 29367 raft_consensus.cc:740] T 00000000000000000000000000000000 P b9f13aefe0e2484aa568c014f8a35773 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: b9f13aefe0e2484aa568c014f8a35773, State: Initialized, Role: FOLLOWER
I20260812 06:19:51.228617 29367 consensus_queue.cc:260] T 00000000000000000000000000000000 P b9f13aefe0e2484aa568c014f8a35773 [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: "b9f13aefe0e2484aa568c014f8a35773" member_type: VOTER }
I20260812 06:19:51.228736 29367 raft_consensus.cc:399] T 00000000000000000000000000000000 P b9f13aefe0e2484aa568c014f8a35773 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:51.228780 29367 raft_consensus.cc:493] T 00000000000000000000000000000000 P b9f13aefe0e2484aa568c014f8a35773 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:51.228860 29367 raft_consensus.cc:3060] T 00000000000000000000000000000000 P b9f13aefe0e2484aa568c014f8a35773 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:51.229518 29367 raft_consensus.cc:515] T 00000000000000000000000000000000 P b9f13aefe0e2484aa568c014f8a35773 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b9f13aefe0e2484aa568c014f8a35773" member_type: VOTER }
I20260812 06:19:51.229861 29367 leader_election.cc:304] T 00000000000000000000000000000000 P b9f13aefe0e2484aa568c014f8a35773 [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: b9f13aefe0e2484aa568c014f8a35773; no voters: 
I20260812 06:19:51.230087 29367 leader_election.cc:290] T 00000000000000000000000000000000 P b9f13aefe0e2484aa568c014f8a35773 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:51.230244 29371 raft_consensus.cc:2804] T 00000000000000000000000000000000 P b9f13aefe0e2484aa568c014f8a35773 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:51.230481 29371 raft_consensus.cc:697] T 00000000000000000000000000000000 P b9f13aefe0e2484aa568c014f8a35773 [term 1 LEADER]: Becoming Leader. State: Replica: b9f13aefe0e2484aa568c014f8a35773, State: Running, Role: LEADER
I20260812 06:19:51.230813 29371 consensus_queue.cc:237] T 00000000000000000000000000000000 P b9f13aefe0e2484aa568c014f8a35773 [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: "b9f13aefe0e2484aa568c014f8a35773" member_type: VOTER }
I20260812 06:19:51.230970 29367 sys_catalog.cc:565] T 00000000000000000000000000000000 P b9f13aefe0e2484aa568c014f8a35773 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:51.232488 29374 sys_catalog.cc:455] T 00000000000000000000000000000000 P b9f13aefe0e2484aa568c014f8a35773 [sys.catalog]: SysCatalogTable state changed. Reason: New leader b9f13aefe0e2484aa568c014f8a35773. Latest consensus state: current_term: 1 leader_uuid: "b9f13aefe0e2484aa568c014f8a35773" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b9f13aefe0e2484aa568c014f8a35773" member_type: VOTER } }
I20260812 06:19:51.232486 29373 sys_catalog.cc:455] T 00000000000000000000000000000000 P b9f13aefe0e2484aa568c014f8a35773 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "b9f13aefe0e2484aa568c014f8a35773" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b9f13aefe0e2484aa568c014f8a35773" member_type: VOTER } }
I20260812 06:19:51.232640 29374 sys_catalog.cc:458] T 00000000000000000000000000000000 P b9f13aefe0e2484aa568c014f8a35773 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:51.232690 29373 sys_catalog.cc:458] T 00000000000000000000000000000000 P b9f13aefe0e2484aa568c014f8a35773 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:51.232982 29389 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:51.233119 29244 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:51.235018 29389 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:51.238968 29389 catalog_manager.cc:1383] Generated new cluster ID: f1a465b035564676b6410bb677c79dc9
I20260812 06:19:51.239027 29389 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:51.263206 29389 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:51.264209 29389 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:51.280195 29389 catalog_manager.cc:6092] T 00000000000000000000000000000000 P b9f13aefe0e2484aa568c014f8a35773: Generated new TSK 0
I20260812 06:19:51.280786 29389 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:51.297466 29244 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:51.299880 29398 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:19:51.299890 29405 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:19:51.300076 29244 server_base.cc:1061] running on GCE node
W20260812 06:19:51.300236 29401 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:19:51.300422 29244 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:51.300474 29244 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:19:51.300498 29244 hybrid_clock.cc:648] HybridClock initialized: now 1786515591300496 us; error 0 us; skew 500 ppm
I20260812 06:19:51.301380 29244 webserver.cc:533] Webserver started at http://127.28.143.1:33649/ using document root <none> and password file <none>
I20260812 06:19:51.301542 29244 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:51.301596 29244 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:51.301668 29244 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:51.302004 29244 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591159890-29244-0/minicluster-data/ts-0-root/instance:
uuid: "d9f9105847cd47a6836f618f1c8087a5"
format_stamp: "Formatted at 2026-08-12 06:19:51 on dist-test-slave-6zbq"
I20260812 06:19:51.303457 29244 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:19:51.304339 29413 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:19:51.304549 29244 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:19:51.304641 29244 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591159890-29244-0/minicluster-data/ts-0-root
uuid: "d9f9105847cd47a6836f618f1c8087a5"
format_stamp: "Formatted at 2026-08-12 06:19:51 on dist-test-slave-6zbq"
I20260812 06:19:51.304749 29244 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591159890-29244-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591159890-29244-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591159890-29244-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:19:51.319651 29244 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:51.320009 29244 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:51.320410 29244 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:51.321197 29244 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:51.321247 29244 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:51.321303 29244 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:51.321334 29244 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:51.327378 29244 rpc_server.cc:307] RPC server started. Bound to: 127.28.143.1:44957
I20260812 06:19:51.327529 29536 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.28.143.1:44957 every 8 connection(s)
I20260812 06:19:51.336658 29538 heartbeater.cc:344] Connected to a master server at 127.28.143.62:45309
I20260812 06:19:51.336874 29538 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:51.337319 29538 heartbeater.cc:507] Master 127.28.143.62:45309 requested a full tablet report, sending...
I20260812 06:19:51.338694 29297 ts_manager.cc:194] Registered new tserver with Master: d9f9105847cd47a6836f618f1c8087a5 (127.28.143.1:44957)
I20260812 06:19:51.339099 29244 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011096535s
I20260812 06:19:51.339818 29297 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:39688
I20260812 06:19:51.347435 29297 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:39696:
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:19:51.359937 29465 tablet_service.cc:1511] Processing CreateTablet for tablet a32398f9b9f24232919a4775e84bed43 (DEFAULT_TABLE table=heavy-update-compaction-test [id=d6982d7ab1214c83a33c60170043defe]), partition=
I20260812 06:19:51.360316 29465 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet a32398f9b9f24232919a4775e84bed43. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:51.362551 29561 tablet_bootstrap.cc:492] T a32398f9b9f24232919a4775e84bed43 P d9f9105847cd47a6836f618f1c8087a5: Bootstrap starting.
I20260812 06:19:51.363441 29561 tablet_bootstrap.cc:654] T a32398f9b9f24232919a4775e84bed43 P d9f9105847cd47a6836f618f1c8087a5: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:51.364843 29561 tablet_bootstrap.cc:492] T a32398f9b9f24232919a4775e84bed43 P d9f9105847cd47a6836f618f1c8087a5: No bootstrap required, opened a new log
I20260812 06:19:51.364924 29561 ts_tablet_manager.cc:1403] T a32398f9b9f24232919a4775e84bed43 P d9f9105847cd47a6836f618f1c8087a5: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:51.365346 29561 raft_consensus.cc:359] T a32398f9b9f24232919a4775e84bed43 P d9f9105847cd47a6836f618f1c8087a5 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d9f9105847cd47a6836f618f1c8087a5" member_type: VOTER last_known_addr { host: "127.28.143.1" port: 44957 } }
I20260812 06:19:51.365437 29561 raft_consensus.cc:385] T a32398f9b9f24232919a4775e84bed43 P d9f9105847cd47a6836f618f1c8087a5 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:51.365458 29561 raft_consensus.cc:740] T a32398f9b9f24232919a4775e84bed43 P d9f9105847cd47a6836f618f1c8087a5 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: d9f9105847cd47a6836f618f1c8087a5, State: Initialized, Role: FOLLOWER
I20260812 06:19:51.365573 29561 consensus_queue.cc:260] T a32398f9b9f24232919a4775e84bed43 P d9f9105847cd47a6836f618f1c8087a5 [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: "d9f9105847cd47a6836f618f1c8087a5" member_type: VOTER last_known_addr { host: "127.28.143.1" port: 44957 } }
I20260812 06:19:51.365653 29561 raft_consensus.cc:399] T a32398f9b9f24232919a4775e84bed43 P d9f9105847cd47a6836f618f1c8087a5 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:51.365682 29561 raft_consensus.cc:493] T a32398f9b9f24232919a4775e84bed43 P d9f9105847cd47a6836f618f1c8087a5 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:51.365729 29561 raft_consensus.cc:3060] T a32398f9b9f24232919a4775e84bed43 P d9f9105847cd47a6836f618f1c8087a5 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:51.366446 29561 raft_consensus.cc:515] T a32398f9b9f24232919a4775e84bed43 P d9f9105847cd47a6836f618f1c8087a5 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d9f9105847cd47a6836f618f1c8087a5" member_type: VOTER last_known_addr { host: "127.28.143.1" port: 44957 } }
I20260812 06:19:51.366562 29561 leader_election.cc:304] T a32398f9b9f24232919a4775e84bed43 P d9f9105847cd47a6836f618f1c8087a5 [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: d9f9105847cd47a6836f618f1c8087a5; no voters: 
I20260812 06:19:51.366732 29561 leader_election.cc:290] T a32398f9b9f24232919a4775e84bed43 P d9f9105847cd47a6836f618f1c8087a5 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:51.366866 29564 raft_consensus.cc:2804] T a32398f9b9f24232919a4775e84bed43 P d9f9105847cd47a6836f618f1c8087a5 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:51.367115 29564 raft_consensus.cc:697] T a32398f9b9f24232919a4775e84bed43 P d9f9105847cd47a6836f618f1c8087a5 [term 1 LEADER]: Becoming Leader. State: Replica: d9f9105847cd47a6836f618f1c8087a5, State: Running, Role: LEADER
I20260812 06:19:51.367120 29561 ts_tablet_manager.cc:1434] T a32398f9b9f24232919a4775e84bed43 P d9f9105847cd47a6836f618f1c8087a5: Time spent starting tablet: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:19:51.367264 29538 heartbeater.cc:499] Master 127.28.143.62:45309 was elected leader, sending a full tablet report...
I20260812 06:19:51.367533 29564 consensus_queue.cc:237] T a32398f9b9f24232919a4775e84bed43 P d9f9105847cd47a6836f618f1c8087a5 [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: "d9f9105847cd47a6836f618f1c8087a5" member_type: VOTER last_known_addr { host: "127.28.143.1" port: 44957 } }
I20260812 06:19:51.369927 29297 catalog_manager.cc:5719] T a32398f9b9f24232919a4775e84bed43 P d9f9105847cd47a6836f618f1c8087a5 reported cstate change: term changed from 0 to 1, leader changed from <none> to d9f9105847cd47a6836f618f1c8087a5 (127.28.143.1). New cstate: current_term: 1 leader_uuid: "d9f9105847cd47a6836f618f1c8087a5" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d9f9105847cd47a6836f618f1c8087a5" member_type: VOTER last_known_addr { host: "127.28.143.1" port: 44957 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:51.424939 29244 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.049s	user 0.010s	sys 0.014s
I20260812 06:19:51.578665 29541 maintenance_manager.cc:419] P d9f9105847cd47a6836f618f1c8087a5: Scheduling FlushMRSOp(a32398f9b9f24232919a4775e84bed43): perf score=23.023690
I20260812 06:19:51.803629 29420 maintenance_manager.cc:643] P d9f9105847cd47a6836f618f1c8087a5: FlushMRSOp(a32398f9b9f24232919a4775e84bed43) complete. Timing: real 0.225s	user 0.170s	sys 0.052s Metrics: {"bytes_written":16409905,"cfile_init":1,"compiler_manager_pool.queue_time_us":194,"delete_count":0,"dirs.queue_time_us":69,"dirs.run_cpu_time_us":225,"dirs.run_wall_time_us":812,"drs_written":1,"lbm_read_time_us":85,"lbm_reads_lt_1ms":4,"lbm_write_time_us":56809,"lbm_writes_lt_1ms":957,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"thread_start_us":107,"threads_started":1,"update_count":2000}
I20260812 06:19:51.805109 29541 maintenance_manager.cc:419] P d9f9105847cd47a6836f618f1c8087a5: Scheduling LogGCOp(a32398f9b9f24232919a4775e84bed43): free 20743880 bytes of WAL
I20260812 06:19:51.805559 29420 log_reader.cc:385] T a32398f9b9f24232919a4775e84bed43: removed 2 log segments from log reader
I20260812 06:19:51.805639 29420 log.cc:1079] T a32398f9b9f24232919a4775e84bed43 P d9f9105847cd47a6836f618f1c8087a5: Deleting log segment in path: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591159890-29244-0/minicluster-data/ts-0-root/wals/a32398f9b9f24232919a4775e84bed43/wal-000000001 (ops 1-6)
I20260812 06:19:51.805699 29420 log.cc:1079] T a32398f9b9f24232919a4775e84bed43 P d9f9105847cd47a6836f618f1c8087a5: Deleting log segment in path: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591159890-29244-0/minicluster-data/ts-0-root/wals/a32398f9b9f24232919a4775e84bed43/wal-000000002 (ops 7-11)
I20260812 06:19:51.809302 29420 maintenance_manager.cc:643] P d9f9105847cd47a6836f618f1c8087a5: LogGCOp(a32398f9b9f24232919a4775e84bed43) complete. Timing: real 0.004s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:19:51.809749 29541 maintenance_manager.cc:419] P d9f9105847cd47a6836f618f1c8087a5: Scheduling FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43): perf score=3.181125
I20260812 06:19:51.825990 29420 maintenance_manager.cc:643] P d9f9105847cd47a6836f618f1c8087a5: FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43) complete. Timing: real 0.016s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4539,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:51.826578 29541 maintenance_manager.cc:419] P d9f9105847cd47a6836f618f1c8087a5: Scheduling UndoDeltaBlockGCOp(a32398f9b9f24232919a4775e84bed43): 20513815 bytes on disk
I20260812 06:19:51.827214 29420 maintenance_manager.cc:643] P d9f9105847cd47a6836f618f1c8087a5: UndoDeltaBlockGCOp(a32398f9b9f24232919a4775e84bed43) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4}
I20260812 06:19:51.827662 29541 maintenance_manager.cc:419] P d9f9105847cd47a6836f618f1c8087a5: Scheduling FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43): perf score=2.188937
I20260812 06:19:51.838997 29420 maintenance_manager.cc:643] P d9f9105847cd47a6836f618f1c8087a5: FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4280,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:51.839510 29541 maintenance_manager.cc:419] P d9f9105847cd47a6836f618f1c8087a5: Scheduling MajorDeltaCompactionOp(a32398f9b9f24232919a4775e84bed43): perf score=1.000000
I20260812 06:19:52.038527 29420 maintenance_manager.cc:643] P d9f9105847cd47a6836f618f1c8087a5: MajorDeltaCompactionOp(a32398f9b9f24232919a4775e84bed43) complete. Timing: real 0.199s	user 0.136s	sys 0.057s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918205,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":553,"lbm_read_time_us":14013,"lbm_reads_lt_1ms":669,"lbm_write_time_us":31077,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"thread_start_us":265,"threads_started":5,"update_count":3000}
I20260812 06:19:52.038978 29541 maintenance_manager.cc:419] P d9f9105847cd47a6836f618f1c8087a5: Scheduling FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43): perf score=14.095187
I20260812 06:19:52.081828 29420 maintenance_manager.cc:643] P d9f9105847cd47a6836f618f1c8087a5: FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43) complete. Timing: real 0.043s	user 0.011s	sys 0.028s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":18846,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:52.082237 29541 maintenance_manager.cc:419] P d9f9105847cd47a6836f618f1c8087a5: Scheduling MajorDeltaCompactionOp(a32398f9b9f24232919a4775e84bed43): perf score=1.000000
I20260812 06:19:52.223047 29420 maintenance_manager.cc:643] P d9f9105847cd47a6836f618f1c8087a5: MajorDeltaCompactionOp(a32398f9b9f24232919a4775e84bed43) complete. Timing: real 0.141s	user 0.095s	sys 0.043s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713154,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":318,"lbm_read_time_us":9847,"lbm_reads_lt_1ms":467,"lbm_write_time_us":23448,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:52.223738 29541 maintenance_manager.cc:419] P d9f9105847cd47a6836f618f1c8087a5: Scheduling FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43): perf score=11.118625
I20260812 06:19:52.257000 29420 maintenance_manager.cc:643] P d9f9105847cd47a6836f618f1c8087a5: FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43) complete. Timing: real 0.033s	user 0.019s	sys 0.012s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":13781,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:52.257496 29541 maintenance_manager.cc:419] P d9f9105847cd47a6836f618f1c8087a5: Scheduling FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43): perf score=2.188937
I20260812 06:19:52.282189 29420 maintenance_manager.cc:643] P d9f9105847cd47a6836f618f1c8087a5: FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43) complete. Timing: real 0.025s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4706,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:52.282683 29541 maintenance_manager.cc:419] P d9f9105847cd47a6836f618f1c8087a5: Scheduling FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43): perf score=2.188937
I20260812 06:19:52.291725 29420 maintenance_manager.cc:643] P d9f9105847cd47a6836f618f1c8087a5: FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3487,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:52.292191 29541 maintenance_manager.cc:419] P d9f9105847cd47a6836f618f1c8087a5: Scheduling MajorDeltaCompactionOp(a32398f9b9f24232919a4775e84bed43): perf score=1.000000
I20260812 06:19:52.463982 29420 maintenance_manager.cc:643] P d9f9105847cd47a6836f618f1c8087a5: MajorDeltaCompactionOp(a32398f9b9f24232919a4775e84bed43) complete. Timing: real 0.172s	user 0.106s	sys 0.051s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815795,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1257,"lbm_read_time_us":9966,"lbm_reads_lt_1ms":573,"lbm_write_time_us":26547,"lbm_writes_lt_1ms":543,"mutex_wait_us":323,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:52.464437 29541 maintenance_manager.cc:419] P d9f9105847cd47a6836f618f1c8087a5: Scheduling FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43): perf score=14.095187
I20260812 06:19:52.509300 29420 maintenance_manager.cc:643] P d9f9105847cd47a6836f618f1c8087a5: FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43) complete. Timing: real 0.045s	user 0.020s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18697,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:52.509809 29541 maintenance_manager.cc:419] P d9f9105847cd47a6836f618f1c8087a5: Scheduling FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43): perf score=2.188937
I20260812 06:19:52.519294 29420 maintenance_manager.cc:643] P d9f9105847cd47a6836f618f1c8087a5: FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43) complete. Timing: real 0.009s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3638,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:52.519759 29541 maintenance_manager.cc:419] P d9f9105847cd47a6836f618f1c8087a5: Scheduling MajorDeltaCompactionOp(a32398f9b9f24232919a4775e84bed43): perf score=1.000000
I20260812 06:19:52.670166 29420 maintenance_manager.cc:643] P d9f9105847cd47a6836f618f1c8087a5: MajorDeltaCompactionOp(a32398f9b9f24232919a4775e84bed43) complete. Timing: real 0.150s	user 0.112s	sys 0.033s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":322,"lbm_read_time_us":9729,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31741,"lbm_writes_lt_1ms":543,"mutex_wait_us":50,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:52.670691 29541 maintenance_manager.cc:419] P d9f9105847cd47a6836f618f1c8087a5: Scheduling FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43): perf score=11.118625
I20260812 06:19:52.704445 29420 maintenance_manager.cc:643] P d9f9105847cd47a6836f618f1c8087a5: FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43) complete. Timing: real 0.034s	user 0.030s	sys 0.001s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":14457,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:52.704908 29541 maintenance_manager.cc:419] P d9f9105847cd47a6836f618f1c8087a5: Scheduling FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43): perf score=2.188937
I20260812 06:19:52.727838 29420 maintenance_manager.cc:643] P d9f9105847cd47a6836f618f1c8087a5: FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43) complete. Timing: real 0.023s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4456,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:52.728271 29541 maintenance_manager.cc:419] P d9f9105847cd47a6836f618f1c8087a5: Scheduling FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43): perf score=2.188937
I20260812 06:19:52.737696 29420 maintenance_manager.cc:643] P d9f9105847cd47a6836f618f1c8087a5: FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43) complete. Timing: real 0.009s	user 0.005s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3691,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:52.738049 29541 maintenance_manager.cc:419] P d9f9105847cd47a6836f618f1c8087a5: Scheduling MajorDeltaCompactionOp(a32398f9b9f24232919a4775e84bed43): perf score=1.000000
I20260812 06:19:52.870568 29420 maintenance_manager.cc:643] P d9f9105847cd47a6836f618f1c8087a5: MajorDeltaCompactionOp(a32398f9b9f24232919a4775e84bed43) complete. Timing: real 0.132s	user 0.101s	sys 0.028s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815796,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1167,"lbm_read_time_us":8659,"lbm_reads_lt_1ms":573,"lbm_write_time_us":25257,"lbm_writes_lt_1ms":543,"mutex_wait_us":304,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4224,"update_count":2500}
I20260812 06:19:52.871037 29541 maintenance_manager.cc:419] P d9f9105847cd47a6836f618f1c8087a5: Scheduling FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43): perf score=11.118625
I20260812 06:19:52.915565 29420 maintenance_manager.cc:643] P d9f9105847cd47a6836f618f1c8087a5: FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43) complete. Timing: real 0.044s	user 0.019s	sys 0.021s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":18480,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:52.916049 29541 maintenance_manager.cc:419] P d9f9105847cd47a6836f618f1c8087a5: Scheduling FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43): perf score=2.188937
I20260812 06:19:52.926319 29420 maintenance_manager.cc:643] P d9f9105847cd47a6836f618f1c8087a5: FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3611,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:52.926730 29541 maintenance_manager.cc:419] P d9f9105847cd47a6836f618f1c8087a5: Scheduling FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43): perf score=2.188937
I20260812 06:19:52.938900 29420 maintenance_manager.cc:643] P d9f9105847cd47a6836f618f1c8087a5: FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43) complete. Timing: real 0.012s	user 0.009s	sys 0.002s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4716,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:52.939255 29541 maintenance_manager.cc:419] P d9f9105847cd47a6836f618f1c8087a5: Scheduling FlushMRSOp(a32398f9b9f24232919a4775e84bed43): perf score=1.000000
I20260812 06:19:52.968977 29420 maintenance_manager.cc:643] P d9f9105847cd47a6836f618f1c8087a5: FlushMRSOp(a32398f9b9f24232919a4775e84bed43) complete. Timing: real 0.030s	user 0.022s	sys 0.004s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":60,"dirs.run_cpu_time_us":243,"dirs.run_wall_time_us":1258,"drs_written":1,"lbm_read_time_us":36,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1555,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:52.969760 29541 maintenance_manager.cc:419] P d9f9105847cd47a6836f618f1c8087a5: Scheduling LogGCOp(a32398f9b9f24232919a4775e84bed43): free 124710286 bytes of WAL
I20260812 06:19:52.969977 29420 log_reader.cc:385] T a32398f9b9f24232919a4775e84bed43: removed 12 log segments from log reader
I20260812 06:19:52.970036 29420 log.cc:1079] T a32398f9b9f24232919a4775e84bed43 P d9f9105847cd47a6836f618f1c8087a5: Deleting log segment in path: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591159890-29244-0/minicluster-data/ts-0-root/wals/a32398f9b9f24232919a4775e84bed43/wal-000000003 (ops 12-16)
I20260812 06:19:52.970081 29420 log.cc:1079] T a32398f9b9f24232919a4775e84bed43 P d9f9105847cd47a6836f618f1c8087a5: Deleting log segment in path: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591159890-29244-0/minicluster-data/ts-0-root/wals/a32398f9b9f24232919a4775e84bed43/wal-000000004 (ops 17-21)
I20260812 06:19:52.970112 29420 log.cc:1079] T a32398f9b9f24232919a4775e84bed43 P d9f9105847cd47a6836f618f1c8087a5: Deleting log segment in path: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591159890-29244-0/minicluster-data/ts-0-root/wals/a32398f9b9f24232919a4775e84bed43/wal-000000005 (ops 22-26)
I20260812 06:19:52.970134 29420 log.cc:1079] T a32398f9b9f24232919a4775e84bed43 P d9f9105847cd47a6836f618f1c8087a5: Deleting log segment in path: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591159890-29244-0/minicluster-data/ts-0-root/wals/a32398f9b9f24232919a4775e84bed43/wal-000000006 (ops 27-31)
I20260812 06:19:52.970161 29420 log.cc:1079] T a32398f9b9f24232919a4775e84bed43 P d9f9105847cd47a6836f618f1c8087a5: Deleting log segment in path: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591159890-29244-0/minicluster-data/ts-0-root/wals/a32398f9b9f24232919a4775e84bed43/wal-000000007 (ops 32-36)
I20260812 06:19:52.970193 29420 log.cc:1079] T a32398f9b9f24232919a4775e84bed43 P d9f9105847cd47a6836f618f1c8087a5: Deleting log segment in path: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591159890-29244-0/minicluster-data/ts-0-root/wals/a32398f9b9f24232919a4775e84bed43/wal-000000008 (ops 37-41)
I20260812 06:19:52.970224 29420 log.cc:1079] T a32398f9b9f24232919a4775e84bed43 P d9f9105847cd47a6836f618f1c8087a5: Deleting log segment in path: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591159890-29244-0/minicluster-data/ts-0-root/wals/a32398f9b9f24232919a4775e84bed43/wal-000000009 (ops 42-46)
I20260812 06:19:52.970252 29420 log.cc:1079] T a32398f9b9f24232919a4775e84bed43 P d9f9105847cd47a6836f618f1c8087a5: Deleting log segment in path: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591159890-29244-0/minicluster-data/ts-0-root/wals/a32398f9b9f24232919a4775e84bed43/wal-000000010 (ops 47-51)
I20260812 06:19:52.970278 29420 log.cc:1079] T a32398f9b9f24232919a4775e84bed43 P d9f9105847cd47a6836f618f1c8087a5: Deleting log segment in path: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591159890-29244-0/minicluster-data/ts-0-root/wals/a32398f9b9f24232919a4775e84bed43/wal-000000011 (ops 52-56)
I20260812 06:19:52.970306 29420 log.cc:1079] T a32398f9b9f24232919a4775e84bed43 P d9f9105847cd47a6836f618f1c8087a5: Deleting log segment in path: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591159890-29244-0/minicluster-data/ts-0-root/wals/a32398f9b9f24232919a4775e84bed43/wal-000000012 (ops 57-61)
I20260812 06:19:52.970357 29420 log.cc:1079] T a32398f9b9f24232919a4775e84bed43 P d9f9105847cd47a6836f618f1c8087a5: Deleting log segment in path: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591159890-29244-0/minicluster-data/ts-0-root/wals/a32398f9b9f24232919a4775e84bed43/wal-000000013 (ops 62-66)
I20260812 06:19:52.970394 29420 log.cc:1079] T a32398f9b9f24232919a4775e84bed43 P d9f9105847cd47a6836f618f1c8087a5: Deleting log segment in path: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591159890-29244-0/minicluster-data/ts-0-root/wals/a32398f9b9f24232919a4775e84bed43/wal-000000014 (ops 67-71)
I20260812 06:19:52.995306 29420 maintenance_manager.cc:643] P d9f9105847cd47a6836f618f1c8087a5: LogGCOp(a32398f9b9f24232919a4775e84bed43) complete. Timing: real 0.025s	user 0.002s	sys 0.023s Metrics: {}
I20260812 06:19:52.995647 29541 maintenance_manager.cc:419] P d9f9105847cd47a6836f618f1c8087a5: Scheduling FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43): perf score=3.181125
I20260812 06:19:53.008913 29420 maintenance_manager.cc:643] P d9f9105847cd47a6836f618f1c8087a5: FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43) complete. Timing: real 0.013s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":3894,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:53.009296 29541 maintenance_manager.cc:419] P d9f9105847cd47a6836f618f1c8087a5: Scheduling UndoDeltaBlockGCOp(a32398f9b9f24232919a4775e84bed43): 471 bytes on disk
I20260812 06:19:53.009692 29420 maintenance_manager.cc:643] P d9f9105847cd47a6836f618f1c8087a5: UndoDeltaBlockGCOp(a32398f9b9f24232919a4775e84bed43) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4}
I20260812 06:19:53.010162 29541 maintenance_manager.cc:419] P d9f9105847cd47a6836f618f1c8087a5: Scheduling FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43): perf score=2.188937
I20260812 06:19:53.024511 29420 maintenance_manager.cc:643] P d9f9105847cd47a6836f618f1c8087a5: FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43) complete. Timing: real 0.014s	user 0.005s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3219,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:53.024823 29541 maintenance_manager.cc:419] P d9f9105847cd47a6836f618f1c8087a5: Scheduling MajorDeltaCompactionOp(a32398f9b9f24232919a4775e84bed43): perf score=1.000000
I20260812 06:19:53.231949 29420 maintenance_manager.cc:643] P d9f9105847cd47a6836f618f1c8087a5: MajorDeltaCompactionOp(a32398f9b9f24232919a4775e84bed43) complete. Timing: real 0.207s	user 0.171s	sys 0.036s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":33020843,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":588,"lbm_read_time_us":15572,"lbm_reads_lt_1ms":775,"lbm_write_time_us":34813,"lbm_writes_lt_1ms":743,"mutex_wait_us":2,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":1664,"thread_start_us":80,"threads_started":1,"update_count":3500}
I20260812 06:19:53.232451 29541 maintenance_manager.cc:419] P d9f9105847cd47a6836f618f1c8087a5: Scheduling FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43): perf score=14.095187
I20260812 06:19:53.278182 29420 maintenance_manager.cc:643] P d9f9105847cd47a6836f618f1c8087a5: FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43) complete. Timing: real 0.046s	user 0.027s	sys 0.015s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":16849,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:53.278589 29541 maintenance_manager.cc:419] P d9f9105847cd47a6836f618f1c8087a5: Scheduling FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43): perf score=2.188937
I20260812 06:19:53.292549 29420 maintenance_manager.cc:643] P d9f9105847cd47a6836f618f1c8087a5: FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43) complete. Timing: real 0.014s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4114,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:53.292989 29541 maintenance_manager.cc:419] P d9f9105847cd47a6836f618f1c8087a5: Scheduling MajorDeltaCompactionOp(a32398f9b9f24232919a4775e84bed43): perf score=1.000000
I20260812 06:19:53.463074 29420 maintenance_manager.cc:643] P d9f9105847cd47a6836f618f1c8087a5: MajorDeltaCompactionOp(a32398f9b9f24232919a4775e84bed43) complete. Timing: real 0.170s	user 0.101s	sys 0.063s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":322,"lbm_read_time_us":11159,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28592,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:19:53.463500 29541 maintenance_manager.cc:419] P d9f9105847cd47a6836f618f1c8087a5: Scheduling FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43): perf score=14.095187
I20260812 06:19:53.522552 29420 maintenance_manager.cc:643] P d9f9105847cd47a6836f618f1c8087a5: FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43) complete. Timing: real 0.059s	user 0.035s	sys 0.023s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21529,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:53.523058 29541 maintenance_manager.cc:419] P d9f9105847cd47a6836f618f1c8087a5: Scheduling FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43): perf score=2.188937
I20260812 06:19:53.532914 29420 maintenance_manager.cc:643] P d9f9105847cd47a6836f618f1c8087a5: FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3744,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:53.533280 29541 maintenance_manager.cc:419] P d9f9105847cd47a6836f618f1c8087a5: Scheduling MajorDeltaCompactionOp(a32398f9b9f24232919a4775e84bed43): perf score=1.000000
I20260812 06:19:53.703577 29420 maintenance_manager.cc:643] P d9f9105847cd47a6836f618f1c8087a5: MajorDeltaCompactionOp(a32398f9b9f24232919a4775e84bed43) complete. Timing: real 0.170s	user 0.094s	sys 0.072s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":120,"lbm_read_time_us":12984,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26464,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:53.704242 29541 maintenance_manager.cc:419] P d9f9105847cd47a6836f618f1c8087a5: Scheduling FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43): perf score=11.118625
I20260812 06:19:53.736192 29420 maintenance_manager.cc:643] P d9f9105847cd47a6836f618f1c8087a5: FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43) complete. Timing: real 0.032s	user 0.018s	sys 0.012s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":13641,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:53.736689 29541 maintenance_manager.cc:419] P d9f9105847cd47a6836f618f1c8087a5: Scheduling FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43): perf score=2.188937
I20260812 06:19:53.759428 29420 maintenance_manager.cc:643] P d9f9105847cd47a6836f618f1c8087a5: FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43) complete. Timing: real 0.023s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5578,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:53.759811 29541 maintenance_manager.cc:419] P d9f9105847cd47a6836f618f1c8087a5: Scheduling FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43): perf score=2.188937
I20260812 06:19:53.774777 29420 maintenance_manager.cc:643] P d9f9105847cd47a6836f618f1c8087a5: FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43) complete. Timing: real 0.015s	user 0.004s	sys 0.010s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3359,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:53.775152 29541 maintenance_manager.cc:419] P d9f9105847cd47a6836f618f1c8087a5: Scheduling MajorDeltaCompactionOp(a32398f9b9f24232919a4775e84bed43): perf score=1.000000
I20260812 06:19:53.940697 29420 maintenance_manager.cc:643] P d9f9105847cd47a6836f618f1c8087a5: MajorDeltaCompactionOp(a32398f9b9f24232919a4775e84bed43) complete. Timing: real 0.165s	user 0.109s	sys 0.043s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815794,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":830,"lbm_read_time_us":11445,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29426,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":542,"mutex_wait_us":293,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12416,"update_count":2500}
I20260812 06:19:53.941228 29541 maintenance_manager.cc:419] P d9f9105847cd47a6836f618f1c8087a5: Scheduling FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43): perf score=14.095187
I20260812 06:19:53.996457 29420 maintenance_manager.cc:643] P d9f9105847cd47a6836f618f1c8087a5: FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43) complete. Timing: real 0.055s	user 0.033s	sys 0.020s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24598,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":400,"reinsert_count":0,"update_count":2000}
I20260812 06:19:53.996935 29541 maintenance_manager.cc:419] P d9f9105847cd47a6836f618f1c8087a5: Scheduling FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43): perf score=2.188937
I20260812 06:19:54.011795 29420 maintenance_manager.cc:643] P d9f9105847cd47a6836f618f1c8087a5: FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43) complete. Timing: real 0.015s	user 0.008s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4244,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:54.012247 29541 maintenance_manager.cc:419] P d9f9105847cd47a6836f618f1c8087a5: Scheduling MajorDeltaCompactionOp(a32398f9b9f24232919a4775e84bed43): perf score=1.000000
I20260812 06:19:54.179817 29420 maintenance_manager.cc:643] P d9f9105847cd47a6836f618f1c8087a5: MajorDeltaCompactionOp(a32398f9b9f24232919a4775e84bed43) complete. Timing: real 0.167s	user 0.129s	sys 0.031s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":549,"lbm_read_time_us":10640,"lbm_reads_lt_1ms":564,"lbm_write_time_us":27010,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":61952,"update_count":2500}
I20260812 06:19:54.180339 29541 maintenance_manager.cc:419] P d9f9105847cd47a6836f618f1c8087a5: Scheduling FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43): perf score=14.095187
I20260812 06:19:54.226172 29420 maintenance_manager.cc:643] P d9f9105847cd47a6836f618f1c8087a5: FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43) complete. Timing: real 0.046s	user 0.035s	sys 0.007s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":20119,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:54.226600 29541 maintenance_manager.cc:419] P d9f9105847cd47a6836f618f1c8087a5: Scheduling FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43): perf score=2.188937
I20260812 06:19:54.236434 29420 maintenance_manager.cc:643] P d9f9105847cd47a6836f618f1c8087a5: FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3762,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:54.237684 29541 maintenance_manager.cc:419] P d9f9105847cd47a6836f618f1c8087a5: Scheduling MajorDeltaCompactionOp(a32398f9b9f24232919a4775e84bed43): perf score=1.000000
I20260812 06:19:54.382652 29420 maintenance_manager.cc:643] P d9f9105847cd47a6836f618f1c8087a5: MajorDeltaCompactionOp(a32398f9b9f24232919a4775e84bed43) complete. Timing: real 0.145s	user 0.092s	sys 0.043s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":77,"lbm_read_time_us":9265,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29086,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":21888,"update_count":2500}
I20260812 06:19:54.383114 29541 maintenance_manager.cc:419] P d9f9105847cd47a6836f618f1c8087a5: Scheduling FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43): perf score=14.095187
I20260812 06:19:54.429648 29420 maintenance_manager.cc:643] P d9f9105847cd47a6836f618f1c8087a5: FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43) complete. Timing: real 0.046s	user 0.021s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19422,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:54.430187 29541 maintenance_manager.cc:419] P d9f9105847cd47a6836f618f1c8087a5: Scheduling FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43): perf score=2.188937
I20260812 06:19:54.440176 29420 maintenance_manager.cc:643] P d9f9105847cd47a6836f618f1c8087a5: FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43) complete. Timing: real 0.010s	user 0.005s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3791,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:54.440676 29541 maintenance_manager.cc:419] P d9f9105847cd47a6836f618f1c8087a5: Scheduling FlushMRSOp(a32398f9b9f24232919a4775e84bed43): perf score=1.000000
I20260812 06:19:54.473563 29420 maintenance_manager.cc:643] P d9f9105847cd47a6836f618f1c8087a5: FlushMRSOp(a32398f9b9f24232919a4775e84bed43) complete. Timing: real 0.033s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":58,"dirs.run_cpu_time_us":237,"dirs.run_wall_time_us":1019,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1433,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:19:54.474313 29541 maintenance_manager.cc:419] P d9f9105847cd47a6836f618f1c8087a5: Scheduling LogGCOp(a32398f9b9f24232919a4775e84bed43): free 133024342 bytes of WAL
I20260812 06:19:54.474570 29420 log_reader.cc:385] T a32398f9b9f24232919a4775e84bed43: removed 13 log segments from log reader
I20260812 06:19:54.474617 29420 log.cc:1079] T a32398f9b9f24232919a4775e84bed43 P d9f9105847cd47a6836f618f1c8087a5: Deleting log segment in path: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591159890-29244-0/minicluster-data/ts-0-root/wals/a32398f9b9f24232919a4775e84bed43/wal-000000015 (ops 72-76)
I20260812 06:19:54.474644 29420 log.cc:1079] T a32398f9b9f24232919a4775e84bed43 P d9f9105847cd47a6836f618f1c8087a5: Deleting log segment in path: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591159890-29244-0/minicluster-data/ts-0-root/wals/a32398f9b9f24232919a4775e84bed43/wal-000000016 (ops 77-80)
I20260812 06:19:54.474663 29420 log.cc:1079] T a32398f9b9f24232919a4775e84bed43 P d9f9105847cd47a6836f618f1c8087a5: Deleting log segment in path: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591159890-29244-0/minicluster-data/ts-0-root/wals/a32398f9b9f24232919a4775e84bed43/wal-000000017 (ops 81-85)
I20260812 06:19:54.474696 29420 log.cc:1079] T a32398f9b9f24232919a4775e84bed43 P d9f9105847cd47a6836f618f1c8087a5: Deleting log segment in path: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591159890-29244-0/minicluster-data/ts-0-root/wals/a32398f9b9f24232919a4775e84bed43/wal-000000018 (ops 86-90)
I20260812 06:19:54.474743 29420 log.cc:1079] T a32398f9b9f24232919a4775e84bed43 P d9f9105847cd47a6836f618f1c8087a5: Deleting log segment in path: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591159890-29244-0/minicluster-data/ts-0-root/wals/a32398f9b9f24232919a4775e84bed43/wal-000000019 (ops 91-95)
I20260812 06:19:54.474764 29420 log.cc:1079] T a32398f9b9f24232919a4775e84bed43 P d9f9105847cd47a6836f618f1c8087a5: Deleting log segment in path: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591159890-29244-0/minicluster-data/ts-0-root/wals/a32398f9b9f24232919a4775e84bed43/wal-000000020 (ops 96-100)
I20260812 06:19:54.474797 29420 log.cc:1079] T a32398f9b9f24232919a4775e84bed43 P d9f9105847cd47a6836f618f1c8087a5: Deleting log segment in path: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591159890-29244-0/minicluster-data/ts-0-root/wals/a32398f9b9f24232919a4775e84bed43/wal-000000021 (ops 101-105)
I20260812 06:19:54.474828 29420 log.cc:1079] T a32398f9b9f24232919a4775e84bed43 P d9f9105847cd47a6836f618f1c8087a5: Deleting log segment in path: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591159890-29244-0/minicluster-data/ts-0-root/wals/a32398f9b9f24232919a4775e84bed43/wal-000000022 (ops 106-110)
I20260812 06:19:54.474860 29420 log.cc:1079] T a32398f9b9f24232919a4775e84bed43 P d9f9105847cd47a6836f618f1c8087a5: Deleting log segment in path: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591159890-29244-0/minicluster-data/ts-0-root/wals/a32398f9b9f24232919a4775e84bed43/wal-000000023 (ops 111-115)
I20260812 06:19:54.474890 29420 log.cc:1079] T a32398f9b9f24232919a4775e84bed43 P d9f9105847cd47a6836f618f1c8087a5: Deleting log segment in path: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591159890-29244-0/minicluster-data/ts-0-root/wals/a32398f9b9f24232919a4775e84bed43/wal-000000024 (ops 116-120)
I20260812 06:19:54.474922 29420 log.cc:1079] T a32398f9b9f24232919a4775e84bed43 P d9f9105847cd47a6836f618f1c8087a5: Deleting log segment in path: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591159890-29244-0/minicluster-data/ts-0-root/wals/a32398f9b9f24232919a4775e84bed43/wal-000000025 (ops 121-125)
I20260812 06:19:54.474953 29420 log.cc:1079] T a32398f9b9f24232919a4775e84bed43 P d9f9105847cd47a6836f618f1c8087a5: Deleting log segment in path: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591159890-29244-0/minicluster-data/ts-0-root/wals/a32398f9b9f24232919a4775e84bed43/wal-000000026 (ops 126-130)
I20260812 06:19:54.474983 29420 log.cc:1079] T a32398f9b9f24232919a4775e84bed43 P d9f9105847cd47a6836f618f1c8087a5: Deleting log segment in path: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591159890-29244-0/minicluster-data/ts-0-root/wals/a32398f9b9f24232919a4775e84bed43/wal-000000027 (ops 131-135)
I20260812 06:19:54.499804 29420 maintenance_manager.cc:643] P d9f9105847cd47a6836f618f1c8087a5: LogGCOp(a32398f9b9f24232919a4775e84bed43) complete. Timing: real 0.025s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:19:54.500406 29541 maintenance_manager.cc:419] P d9f9105847cd47a6836f618f1c8087a5: Scheduling FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43): perf score=4.173312
I20260812 06:19:54.525269 29420 maintenance_manager.cc:643] P d9f9105847cd47a6836f618f1c8087a5: FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43) complete. Timing: real 0.025s	user 0.015s	sys 0.006s Metrics: {"bytes_written":6400017,"delete_count":0,"lbm_write_time_us":7042,"lbm_writes_lt_1ms":159,"reinsert_count":0,"update_count":780}
I20260812 06:19:54.525790 29541 maintenance_manager.cc:419] P d9f9105847cd47a6836f618f1c8087a5: Scheduling FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43): perf score=1.000000
I20260812 06:19:54.532217 29420 maintenance_manager.cc:643] P d9f9105847cd47a6836f618f1c8087a5: FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43) complete. Timing: real 0.006s	user 0.002s	sys 0.003s Metrics: {"bytes_written":1805252,"delete_count":0,"lbm_write_time_us":1801,"lbm_writes_lt_1ms":47,"reinsert_count":0,"update_count":220}
I20260812 06:19:54.532754 29541 maintenance_manager.cc:419] P d9f9105847cd47a6836f618f1c8087a5: Scheduling MajorDeltaCompactionOp(a32398f9b9f24232919a4775e84bed43): perf score=1.000000
I20260812 06:19:54.741312 29420 maintenance_manager.cc:643] P d9f9105847cd47a6836f618f1c8087a5: MajorDeltaCompactionOp(a32398f9b9f24232919a4775e84bed43) complete. Timing: real 0.208s	user 0.142s	sys 0.061s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020691,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":253,"lbm_read_time_us":13985,"lbm_reads_lt_1ms":774,"lbm_write_time_us":36103,"lbm_writes_lt_1ms":743,"mutex_wait_us":25,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":9088,"thread_start_us":68,"threads_started":1,"update_count":3500}
I20260812 06:19:54.742703 29541 maintenance_manager.cc:419] P d9f9105847cd47a6836f618f1c8087a5: Scheduling UndoDeltaBlockGCOp(a32398f9b9f24232919a4775e84bed43): 493 bytes on disk
I20260812 06:19:54.743155 29420 maintenance_manager.cc:643] P d9f9105847cd47a6836f618f1c8087a5: UndoDeltaBlockGCOp(a32398f9b9f24232919a4775e84bed43) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4}
I20260812 06:19:54.743752 29541 maintenance_manager.cc:419] P d9f9105847cd47a6836f618f1c8087a5: Scheduling FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43): perf score=15.087375
I20260812 06:19:54.796558 29420 maintenance_manager.cc:643] P d9f9105847cd47a6836f618f1c8087a5: FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43) complete. Timing: real 0.053s	user 0.027s	sys 0.012s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":18013,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:19:54.797089 29541 maintenance_manager.cc:419] P d9f9105847cd47a6836f618f1c8087a5: Scheduling FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43): perf score=2.188937
I20260812 06:19:54.813094 29420 maintenance_manager.cc:643] P d9f9105847cd47a6836f618f1c8087a5: FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43) complete. Timing: real 0.016s	user 0.011s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6513,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:54.813455 29541 maintenance_manager.cc:419] P d9f9105847cd47a6836f618f1c8087a5: Scheduling FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43): perf score=2.188937
I20260812 06:19:54.821974 29420 maintenance_manager.cc:643] P d9f9105847cd47a6836f618f1c8087a5: FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43) complete. Timing: real 0.008s	user 0.003s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3274,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:54.822290 29541 maintenance_manager.cc:419] P d9f9105847cd47a6836f618f1c8087a5: Scheduling MajorDeltaCompactionOp(a32398f9b9f24232919a4775e84bed43): perf score=1.000000
I20260812 06:19:55.010222 29420 maintenance_manager.cc:643] P d9f9105847cd47a6836f618f1c8087a5: MajorDeltaCompactionOp(a32398f9b9f24232919a4775e84bed43) complete. Timing: real 0.188s	user 0.106s	sys 0.081s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918201,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":771,"lbm_read_time_us":12558,"lbm_reads_lt_1ms":673,"lbm_write_time_us":33078,"lbm_writes_lt_1ms":643,"mutex_wait_us":31,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":8832,"update_count":3000}
I20260812 06:19:55.010771 29541 maintenance_manager.cc:419] P d9f9105847cd47a6836f618f1c8087a5: Scheduling FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43): perf score=14.095187
I20260812 06:19:55.068126 29420 maintenance_manager.cc:643] P d9f9105847cd47a6836f618f1c8087a5: FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43) complete. Timing: real 0.057s	user 0.035s	sys 0.007s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":19748,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:55.068607 29541 maintenance_manager.cc:419] P d9f9105847cd47a6836f618f1c8087a5: Scheduling FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43): perf score=2.188937
I20260812 06:19:55.080726 29420 maintenance_manager.cc:643] P d9f9105847cd47a6836f618f1c8087a5: FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43) complete. Timing: real 0.012s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4353,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:55.081281 29541 maintenance_manager.cc:419] P d9f9105847cd47a6836f618f1c8087a5: Scheduling MajorDeltaCompactionOp(a32398f9b9f24232919a4775e84bed43): perf score=1.000000
I20260812 06:19:55.242316 29420 maintenance_manager.cc:643] P d9f9105847cd47a6836f618f1c8087a5: MajorDeltaCompactionOp(a32398f9b9f24232919a4775e84bed43) complete. Timing: real 0.160s	user 0.099s	sys 0.061s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":352,"lbm_read_time_us":10825,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29354,"lbm_writes_lt_1ms":543,"mutex_wait_us":20,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":87424,"update_count":2500}
I20260812 06:19:55.242959 29541 maintenance_manager.cc:419] P d9f9105847cd47a6836f618f1c8087a5: Scheduling FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43): perf score=14.095187
I20260812 06:19:55.296110 29420 maintenance_manager.cc:643] P d9f9105847cd47a6836f618f1c8087a5: FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43) complete. Timing: real 0.053s	user 0.024s	sys 0.019s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":19248,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:55.296633 29541 maintenance_manager.cc:419] P d9f9105847cd47a6836f618f1c8087a5: Scheduling FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43): perf score=2.188937
I20260812 06:19:55.306154 29420 maintenance_manager.cc:643] P d9f9105847cd47a6836f618f1c8087a5: FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43) complete. Timing: real 0.009s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3754,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:55.306632 29541 maintenance_manager.cc:419] P d9f9105847cd47a6836f618f1c8087a5: Scheduling MajorDeltaCompactionOp(a32398f9b9f24232919a4775e84bed43): perf score=1.000000
I20260812 06:19:55.473831 29420 maintenance_manager.cc:643] P d9f9105847cd47a6836f618f1c8087a5: MajorDeltaCompactionOp(a32398f9b9f24232919a4775e84bed43) complete. Timing: real 0.167s	user 0.100s	sys 0.061s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":131,"lbm_read_time_us":11861,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28310,"lbm_writes_lt_1ms":543,"mutex_wait_us":19,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":26368,"update_count":2500}
I20260812 06:19:55.474438 29541 maintenance_manager.cc:419] P d9f9105847cd47a6836f618f1c8087a5: Scheduling FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43): perf score=14.095187
I20260812 06:19:55.524538 29420 maintenance_manager.cc:643] P d9f9105847cd47a6836f618f1c8087a5: FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43) complete. Timing: real 0.050s	user 0.026s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17122,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:55.525125 29541 maintenance_manager.cc:419] P d9f9105847cd47a6836f618f1c8087a5: Scheduling FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43): perf score=2.188937
I20260812 06:19:55.534963 29420 maintenance_manager.cc:643] P d9f9105847cd47a6836f618f1c8087a5: FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3800,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:55.535423 29541 maintenance_manager.cc:419] P d9f9105847cd47a6836f618f1c8087a5: Scheduling MajorDeltaCompactionOp(a32398f9b9f24232919a4775e84bed43): perf score=1.000000
I20260812 06:19:55.693873 29420 maintenance_manager.cc:643] P d9f9105847cd47a6836f618f1c8087a5: MajorDeltaCompactionOp(a32398f9b9f24232919a4775e84bed43) complete. Timing: real 0.158s	user 0.114s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":132,"lbm_read_time_us":11858,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27017,"lbm_writes_lt_1ms":543,"mutex_wait_us":15,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5632,"update_count":2500}
I20260812 06:19:55.694973 29541 maintenance_manager.cc:419] P d9f9105847cd47a6836f618f1c8087a5: Scheduling FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43): perf score=10.126437
I20260812 06:19:55.729058 29420 maintenance_manager.cc:643] P d9f9105847cd47a6836f618f1c8087a5: FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43) complete. Timing: real 0.034s	user 0.023s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14826,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:55.729514 29541 maintenance_manager.cc:419] P d9f9105847cd47a6836f618f1c8087a5: Scheduling FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43): perf score=2.188937
I20260812 06:19:55.743741 29420 maintenance_manager.cc:643] P d9f9105847cd47a6836f618f1c8087a5: FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4918,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:55.744190 29541 maintenance_manager.cc:419] P d9f9105847cd47a6836f618f1c8087a5: Scheduling FlushMRSOp(a32398f9b9f24232919a4775e84bed43): perf score=1.000000
I20260812 06:19:55.770009 29420 maintenance_manager.cc:643] P d9f9105847cd47a6836f618f1c8087a5: FlushMRSOp(a32398f9b9f24232919a4775e84bed43) complete. Timing: real 0.026s	user 0.024s	sys 0.000s Metrics: {"bytes_written":1152512,"cfile_init":1,"dirs.queue_time_us":32,"dirs.run_cpu_time_us":157,"dirs.run_wall_time_us":977,"drs_written":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1550,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:55.770668 29541 maintenance_manager.cc:419] P d9f9105847cd47a6836f618f1c8087a5: Scheduling LogGCOp(a32398f9b9f24232919a4775e84bed43): free 112239612 bytes of WAL
I20260812 06:19:55.770879 29420 log_reader.cc:385] T a32398f9b9f24232919a4775e84bed43: removed 11 log segments from log reader
I20260812 06:19:55.770933 29420 log.cc:1079] T a32398f9b9f24232919a4775e84bed43 P d9f9105847cd47a6836f618f1c8087a5: Deleting log segment in path: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591159890-29244-0/minicluster-data/ts-0-root/wals/a32398f9b9f24232919a4775e84bed43/wal-000000028 (ops 136-140)
I20260812 06:19:55.770974 29420 log.cc:1079] T a32398f9b9f24232919a4775e84bed43 P d9f9105847cd47a6836f618f1c8087a5: Deleting log segment in path: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591159890-29244-0/minicluster-data/ts-0-root/wals/a32398f9b9f24232919a4775e84bed43/wal-000000029 (ops 141-145)
I20260812 06:19:55.771005 29420 log.cc:1079] T a32398f9b9f24232919a4775e84bed43 P d9f9105847cd47a6836f618f1c8087a5: Deleting log segment in path: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591159890-29244-0/minicluster-data/ts-0-root/wals/a32398f9b9f24232919a4775e84bed43/wal-000000030 (ops 146-150)
I20260812 06:19:55.771040 29420 log.cc:1079] T a32398f9b9f24232919a4775e84bed43 P d9f9105847cd47a6836f618f1c8087a5: Deleting log segment in path: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591159890-29244-0/minicluster-data/ts-0-root/wals/a32398f9b9f24232919a4775e84bed43/wal-000000031 (ops 151-154)
I20260812 06:19:55.771070 29420 log.cc:1079] T a32398f9b9f24232919a4775e84bed43 P d9f9105847cd47a6836f618f1c8087a5: Deleting log segment in path: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591159890-29244-0/minicluster-data/ts-0-root/wals/a32398f9b9f24232919a4775e84bed43/wal-000000032 (ops 155-159)
I20260812 06:19:55.771099 29420 log.cc:1079] T a32398f9b9f24232919a4775e84bed43 P d9f9105847cd47a6836f618f1c8087a5: Deleting log segment in path: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591159890-29244-0/minicluster-data/ts-0-root/wals/a32398f9b9f24232919a4775e84bed43/wal-000000033 (ops 160-164)
I20260812 06:19:55.771126 29420 log.cc:1079] T a32398f9b9f24232919a4775e84bed43 P d9f9105847cd47a6836f618f1c8087a5: Deleting log segment in path: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591159890-29244-0/minicluster-data/ts-0-root/wals/a32398f9b9f24232919a4775e84bed43/wal-000000034 (ops 165-169)
I20260812 06:19:55.771154 29420 log.cc:1079] T a32398f9b9f24232919a4775e84bed43 P d9f9105847cd47a6836f618f1c8087a5: Deleting log segment in path: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591159890-29244-0/minicluster-data/ts-0-root/wals/a32398f9b9f24232919a4775e84bed43/wal-000000035 (ops 170-174)
I20260812 06:19:55.771188 29420 log.cc:1079] T a32398f9b9f24232919a4775e84bed43 P d9f9105847cd47a6836f618f1c8087a5: Deleting log segment in path: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591159890-29244-0/minicluster-data/ts-0-root/wals/a32398f9b9f24232919a4775e84bed43/wal-000000036 (ops 175-179)
I20260812 06:19:55.771216 29420 log.cc:1079] T a32398f9b9f24232919a4775e84bed43 P d9f9105847cd47a6836f618f1c8087a5: Deleting log segment in path: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591159890-29244-0/minicluster-data/ts-0-root/wals/a32398f9b9f24232919a4775e84bed43/wal-000000037 (ops 180-184)
I20260812 06:19:55.771245 29420 log.cc:1079] T a32398f9b9f24232919a4775e84bed43 P d9f9105847cd47a6836f618f1c8087a5: Deleting log segment in path: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591159890-29244-0/minicluster-data/ts-0-root/wals/a32398f9b9f24232919a4775e84bed43/wal-000000038 (ops 185-189)
I20260812 06:19:55.795786 29420 maintenance_manager.cc:643] P d9f9105847cd47a6836f618f1c8087a5: LogGCOp(a32398f9b9f24232919a4775e84bed43) complete. Timing: real 0.025s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:19:55.796128 29541 maintenance_manager.cc:419] P d9f9105847cd47a6836f618f1c8087a5: Scheduling FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43): perf score=3.181125
I20260812 06:19:55.816823 29420 maintenance_manager.cc:643] P d9f9105847cd47a6836f618f1c8087a5: FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43) complete. Timing: real 0.021s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4063,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:55.817291 29541 maintenance_manager.cc:419] P d9f9105847cd47a6836f618f1c8087a5: Scheduling UndoDeltaBlockGCOp(a32398f9b9f24232919a4775e84bed43): 446 bytes on disk
I20260812 06:19:55.817744 29420 maintenance_manager.cc:643] P d9f9105847cd47a6836f618f1c8087a5: UndoDeltaBlockGCOp(a32398f9b9f24232919a4775e84bed43) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":68,"lbm_reads_lt_1ms":4}
I20260812 06:19:55.818252 29541 maintenance_manager.cc:419] P d9f9105847cd47a6836f618f1c8087a5: Scheduling FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43): perf score=2.188937
I20260812 06:19:55.831447 29420 maintenance_manager.cc:643] P d9f9105847cd47a6836f618f1c8087a5: FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43) complete. Timing: real 0.013s	user 0.007s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4781,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:55.831897 29541 maintenance_manager.cc:419] P d9f9105847cd47a6836f618f1c8087a5: Scheduling MajorDeltaCompactionOp(a32398f9b9f24232919a4775e84bed43): perf score=1.000000
I20260812 06:19:55.999022 29244 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.574s	user 1.616s	sys 0.162s
I20260812 06:19:56.013010 29420 maintenance_manager.cc:643] P d9f9105847cd47a6836f618f1c8087a5: MajorDeltaCompactionOp(a32398f9b9f24232919a4775e84bed43) complete. Timing: real 0.181s	user 0.144s	sys 0.035s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918320,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":12300,"lbm_reads_lt_1ms":670,"lbm_write_time_us":31544,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:19:56.013449 29541 maintenance_manager.cc:419] P d9f9105847cd47a6836f618f1c8087a5: Scheduling FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43): perf score=14.095187
I20260812 06:19:56.043263 29420 maintenance_manager.cc:643] P d9f9105847cd47a6836f618f1c8087a5: FlushDeltaMemStoresOp(a32398f9b9f24232919a4775e84bed43) complete. Timing: real 0.030s	user 0.016s	sys 0.012s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":13877,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:56.043694 29541 maintenance_manager.cc:419] P d9f9105847cd47a6836f618f1c8087a5: Scheduling MajorDeltaCompactionOp(a32398f9b9f24232919a4775e84bed43): perf score=1.000000
I20260812 06:19:56.070734 29244 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.071s	user 0.003s	sys 0.000s
I20260812 06:19:56.071341 29244 tablet_server.cc:179] TabletServer@127.28.143.1:0 shutting down...
I20260812 06:19:56.163170 29420 maintenance_manager.cc:643] P d9f9105847cd47a6836f618f1c8087a5: MajorDeltaCompactionOp(a32398f9b9f24232919a4775e84bed43) complete. Timing: real 0.119s	user 0.058s	sys 0.060s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713154,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1070,"lbm_read_time_us":7193,"lbm_reads_lt_1ms":467,"lbm_write_time_us":20586,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":306,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2000}
I20260812 06:19:56.163764 29244 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:56.164116 29244 tablet_replica.cc:333] T a32398f9b9f24232919a4775e84bed43 P d9f9105847cd47a6836f618f1c8087a5: stopping tablet replica
I20260812 06:19:56.164323 29244 raft_consensus.cc:2243] T a32398f9b9f24232919a4775e84bed43 P d9f9105847cd47a6836f618f1c8087a5 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:56.164529 29244 raft_consensus.cc:2272] T a32398f9b9f24232919a4775e84bed43 P d9f9105847cd47a6836f618f1c8087a5 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:56.179867 29244 tablet_server.cc:196] TabletServer@127.28.143.1:0 shutdown complete.
I20260812 06:19:56.203737 29244 master.cc:562] Master@127.28.143.62:45309 shutting down...
I20260812 06:19:56.206648 29244 raft_consensus.cc:2243] T 00000000000000000000000000000000 P b9f13aefe0e2484aa568c014f8a35773 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:56.206787 29244 raft_consensus.cc:2272] T 00000000000000000000000000000000 P b9f13aefe0e2484aa568c014f8a35773 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:56.206856 29244 tablet_replica.cc:333] T 00000000000000000000000000000000 P b9f13aefe0e2484aa568c014f8a35773: stopping tablet replica
I20260812 06:19:56.218710 29244 master.cc:584] Master@127.28.143.62:45309 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5122 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:19:56.292058 29244 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.28.143.62:42547
I20260812 06:19:56.292383 29244 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:56.294148 29595 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:19:56.294235 29244 server_base.cc:1061] running on GCE node
W20260812 06:19:56.294313 29598 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:19:56.294402 29594 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:19:56.294580 29244 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:56.294625 29244 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:19:56.294639 29244 hybrid_clock.cc:648] HybridClock initialized: now 1786515596294640 us; error 0 us; skew 500 ppm
I20260812 06:19:56.295413 29244 webserver.cc:533] Webserver started at http://127.28.143.62:41055/ using document root <none> and password file <none>
I20260812 06:19:56.295549 29244 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:56.295593 29244 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:56.295646 29244 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:56.295974 29244 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591159890-29244-0/minicluster-data/master-0-root/instance:
uuid: "f11a004722db4f2799d2aa581015bd65"
format_stamp: "Formatted at 2026-08-12 06:19:56 on dist-test-slave-6zbq"
I20260812 06:19:56.306469 29244 fs_manager.cc:696] Time spent creating directory manager: real 0.010s	user 0.002s	sys 0.000s
I20260812 06:19:56.307477 29608 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:19:56.307845 29244 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:56.307929 29244 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591159890-29244-0/minicluster-data/master-0-root
uuid: "f11a004722db4f2799d2aa581015bd65"
format_stamp: "Formatted at 2026-08-12 06:19:56 on dist-test-slave-6zbq"
I20260812 06:19:56.308007 29244 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591159890-29244-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591159890-29244-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591159890-29244-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:19:56.318075 29244 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:56.318480 29244 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:56.322793 29244 rpc_server.cc:307] RPC server started. Bound to: 127.28.143.62:42547
I20260812 06:19:56.333995 29699 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.28.143.62:42547 every 8 connection(s)
I20260812 06:19:56.337939 29701 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:19:56.340003 29701 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P f11a004722db4f2799d2aa581015bd65: Bootstrap starting.
I20260812 06:19:56.340732 29701 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P f11a004722db4f2799d2aa581015bd65: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:56.341691 29701 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P f11a004722db4f2799d2aa581015bd65: No bootstrap required, opened a new log
I20260812 06:19:56.342053 29701 raft_consensus.cc:359] T 00000000000000000000000000000000 P f11a004722db4f2799d2aa581015bd65 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f11a004722db4f2799d2aa581015bd65" member_type: VOTER }
I20260812 06:19:56.342140 29701 raft_consensus.cc:385] T 00000000000000000000000000000000 P f11a004722db4f2799d2aa581015bd65 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:56.342175 29701 raft_consensus.cc:740] T 00000000000000000000000000000000 P f11a004722db4f2799d2aa581015bd65 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: f11a004722db4f2799d2aa581015bd65, State: Initialized, Role: FOLLOWER
I20260812 06:19:56.342311 29701 consensus_queue.cc:260] T 00000000000000000000000000000000 P f11a004722db4f2799d2aa581015bd65 [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: "f11a004722db4f2799d2aa581015bd65" member_type: VOTER }
I20260812 06:19:56.342437 29701 raft_consensus.cc:399] T 00000000000000000000000000000000 P f11a004722db4f2799d2aa581015bd65 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:56.342481 29701 raft_consensus.cc:493] T 00000000000000000000000000000000 P f11a004722db4f2799d2aa581015bd65 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:56.342531 29701 raft_consensus.cc:3060] T 00000000000000000000000000000000 P f11a004722db4f2799d2aa581015bd65 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:56.343138 29701 raft_consensus.cc:515] T 00000000000000000000000000000000 P f11a004722db4f2799d2aa581015bd65 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f11a004722db4f2799d2aa581015bd65" member_type: VOTER }
I20260812 06:19:56.343253 29701 leader_election.cc:304] T 00000000000000000000000000000000 P f11a004722db4f2799d2aa581015bd65 [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: f11a004722db4f2799d2aa581015bd65; no voters: 
I20260812 06:19:56.343425 29701 leader_election.cc:290] T 00000000000000000000000000000000 P f11a004722db4f2799d2aa581015bd65 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:56.343542 29708 raft_consensus.cc:2804] T 00000000000000000000000000000000 P f11a004722db4f2799d2aa581015bd65 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:56.343748 29708 raft_consensus.cc:697] T 00000000000000000000000000000000 P f11a004722db4f2799d2aa581015bd65 [term 1 LEADER]: Becoming Leader. State: Replica: f11a004722db4f2799d2aa581015bd65, State: Running, Role: LEADER
I20260812 06:19:56.343822 29701 sys_catalog.cc:565] T 00000000000000000000000000000000 P f11a004722db4f2799d2aa581015bd65 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:56.343896 29708 consensus_queue.cc:237] T 00000000000000000000000000000000 P f11a004722db4f2799d2aa581015bd65 [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: "f11a004722db4f2799d2aa581015bd65" member_type: VOTER }
I20260812 06:19:56.344328 29711 sys_catalog.cc:455] T 00000000000000000000000000000000 P f11a004722db4f2799d2aa581015bd65 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "f11a004722db4f2799d2aa581015bd65" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f11a004722db4f2799d2aa581015bd65" member_type: VOTER } }
I20260812 06:19:56.344432 29711 sys_catalog.cc:458] T 00000000000000000000000000000000 P f11a004722db4f2799d2aa581015bd65 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:56.344339 29713 sys_catalog.cc:455] T 00000000000000000000000000000000 P f11a004722db4f2799d2aa581015bd65 [sys.catalog]: SysCatalogTable state changed. Reason: New leader f11a004722db4f2799d2aa581015bd65. Latest consensus state: current_term: 1 leader_uuid: "f11a004722db4f2799d2aa581015bd65" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f11a004722db4f2799d2aa581015bd65" member_type: VOTER } }
I20260812 06:19:56.344549 29713 sys_catalog.cc:458] T 00000000000000000000000000000000 P f11a004722db4f2799d2aa581015bd65 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:56.345018 29723 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:56.345906 29723 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:56.346026 29244 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:56.347813 29723 catalog_manager.cc:1383] Generated new cluster ID: e927815e5a1b4affafe915067ce9b805
I20260812 06:19:56.347868 29723 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:56.386240 29723 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:56.386765 29723 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:56.396726 29723 catalog_manager.cc:6092] T 00000000000000000000000000000000 P f11a004722db4f2799d2aa581015bd65: Generated new TSK 0
I20260812 06:19:56.396868 29723 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:56.410364 29244 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:56.412042 29746 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:19:56.412220 29748 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:19:56.412418 29244 server_base.cc:1061] running on GCE node
W20260812 06:19:56.412245 29751 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:19:56.412663 29244 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:56.412705 29244 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:19:56.412719 29244 hybrid_clock.cc:648] HybridClock initialized: now 1786515596412719 us; error 0 us; skew 500 ppm
I20260812 06:19:56.413494 29244 webserver.cc:533] Webserver started at http://127.28.143.1:33813/ using document root <none> and password file <none>
I20260812 06:19:56.413630 29244 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:56.413679 29244 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:56.413749 29244 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:56.414079 29244 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591159890-29244-0/minicluster-data/ts-0-root/instance:
uuid: "4ed50b40d9a947ae95122281383b2955"
format_stamp: "Formatted at 2026-08-12 06:19:56 on dist-test-slave-6zbq"
I20260812 06:19:56.415498 29244 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:56.416404 29764 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:19:56.416647 29244 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:56.416713 29244 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591159890-29244-0/minicluster-data/ts-0-root
uuid: "4ed50b40d9a947ae95122281383b2955"
format_stamp: "Formatted at 2026-08-12 06:19:56 on dist-test-slave-6zbq"
I20260812 06:19:56.416777 29244 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591159890-29244-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591159890-29244-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591159890-29244-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:19:56.440765 29244 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:56.441035 29244 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:56.441298 29244 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:56.441684 29244 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:56.441720 29244 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:56.441759 29244 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:56.441787 29244 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:56.445796 29244 rpc_server.cc:307] RPC server started. Bound to: 127.28.143.1:34163
I20260812 06:19:56.445839 29871 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.28.143.1:34163 every 8 connection(s)
I20260812 06:19:56.454021 29873 heartbeater.cc:344] Connected to a master server at 127.28.143.62:42547
I20260812 06:19:56.454123 29873 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:56.454365 29873 heartbeater.cc:507] Master 127.28.143.62:42547 requested a full tablet report, sending...
I20260812 06:19:56.454985 29637 ts_manager.cc:194] Registered new tserver with Master: 4ed50b40d9a947ae95122281383b2955 (127.28.143.1:34163)
I20260812 06:19:56.455638 29637 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:50664
I20260812 06:19:56.456036 29244 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.00985886s
I20260812 06:19:56.462972 29637 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:50680:
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:19:56.471755 29807 tablet_service.cc:1511] Processing CreateTablet for tablet 2f18854b61f24c9988d39c053b7131c4 (DEFAULT_TABLE table=heavy-update-compaction-test [id=642c769766fd4217aa5ac91ba1120639]), partition=
I20260812 06:19:56.472013 29807 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 2f18854b61f24c9988d39c053b7131c4. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:56.474481 29899 tablet_bootstrap.cc:492] T 2f18854b61f24c9988d39c053b7131c4 P 4ed50b40d9a947ae95122281383b2955: Bootstrap starting.
I20260812 06:19:56.475467 29899 tablet_bootstrap.cc:654] T 2f18854b61f24c9988d39c053b7131c4 P 4ed50b40d9a947ae95122281383b2955: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:56.476637 29899 tablet_bootstrap.cc:492] T 2f18854b61f24c9988d39c053b7131c4 P 4ed50b40d9a947ae95122281383b2955: No bootstrap required, opened a new log
I20260812 06:19:56.476787 29899 ts_tablet_manager.cc:1403] T 2f18854b61f24c9988d39c053b7131c4 P 4ed50b40d9a947ae95122281383b2955: Time spent bootstrapping tablet: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:19:56.477167 29899 raft_consensus.cc:359] T 2f18854b61f24c9988d39c053b7131c4 P 4ed50b40d9a947ae95122281383b2955 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4ed50b40d9a947ae95122281383b2955" member_type: VOTER last_known_addr { host: "127.28.143.1" port: 34163 } }
I20260812 06:19:56.477248 29899 raft_consensus.cc:385] T 2f18854b61f24c9988d39c053b7131c4 P 4ed50b40d9a947ae95122281383b2955 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:56.477279 29899 raft_consensus.cc:740] T 2f18854b61f24c9988d39c053b7131c4 P 4ed50b40d9a947ae95122281383b2955 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 4ed50b40d9a947ae95122281383b2955, State: Initialized, Role: FOLLOWER
I20260812 06:19:56.477406 29899 consensus_queue.cc:260] T 2f18854b61f24c9988d39c053b7131c4 P 4ed50b40d9a947ae95122281383b2955 [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: "4ed50b40d9a947ae95122281383b2955" member_type: VOTER last_known_addr { host: "127.28.143.1" port: 34163 } }
I20260812 06:19:56.477492 29899 raft_consensus.cc:399] T 2f18854b61f24c9988d39c053b7131c4 P 4ed50b40d9a947ae95122281383b2955 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:56.477532 29899 raft_consensus.cc:493] T 2f18854b61f24c9988d39c053b7131c4 P 4ed50b40d9a947ae95122281383b2955 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:56.477579 29899 raft_consensus.cc:3060] T 2f18854b61f24c9988d39c053b7131c4 P 4ed50b40d9a947ae95122281383b2955 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:56.478237 29899 raft_consensus.cc:515] T 2f18854b61f24c9988d39c053b7131c4 P 4ed50b40d9a947ae95122281383b2955 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4ed50b40d9a947ae95122281383b2955" member_type: VOTER last_known_addr { host: "127.28.143.1" port: 34163 } }
I20260812 06:19:56.478389 29899 leader_election.cc:304] T 2f18854b61f24c9988d39c053b7131c4 P 4ed50b40d9a947ae95122281383b2955 [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: 4ed50b40d9a947ae95122281383b2955; no voters: 
I20260812 06:19:56.478564 29899 leader_election.cc:290] T 2f18854b61f24c9988d39c053b7131c4 P 4ed50b40d9a947ae95122281383b2955 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:56.478714 29902 raft_consensus.cc:2804] T 2f18854b61f24c9988d39c053b7131c4 P 4ed50b40d9a947ae95122281383b2955 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:56.478889 29873 heartbeater.cc:499] Master 127.28.143.62:42547 was elected leader, sending a full tablet report...
I20260812 06:19:56.478998 29902 raft_consensus.cc:697] T 2f18854b61f24c9988d39c053b7131c4 P 4ed50b40d9a947ae95122281383b2955 [term 1 LEADER]: Becoming Leader. State: Replica: 4ed50b40d9a947ae95122281383b2955, State: Running, Role: LEADER
I20260812 06:19:56.478893 29899 ts_tablet_manager.cc:1434] T 2f18854b61f24c9988d39c053b7131c4 P 4ed50b40d9a947ae95122281383b2955: Time spent starting tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:56.479161 29902 consensus_queue.cc:237] T 2f18854b61f24c9988d39c053b7131c4 P 4ed50b40d9a947ae95122281383b2955 [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: "4ed50b40d9a947ae95122281383b2955" member_type: VOTER last_known_addr { host: "127.28.143.1" port: 34163 } }
I20260812 06:19:56.480623 29637 catalog_manager.cc:5719] T 2f18854b61f24c9988d39c053b7131c4 P 4ed50b40d9a947ae95122281383b2955 reported cstate change: term changed from 0 to 1, leader changed from <none> to 4ed50b40d9a947ae95122281383b2955 (127.28.143.1). New cstate: current_term: 1 leader_uuid: "4ed50b40d9a947ae95122281383b2955" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4ed50b40d9a947ae95122281383b2955" member_type: VOTER last_known_addr { host: "127.28.143.1" port: 34163 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:56.542498 29244 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.055s	user 0.021s	sys 0.004s
I20260812 06:19:56.696679 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling FlushMRSOp(2f18854b61f24c9988d39c053b7131c4): perf score=19.054940
I20260812 06:19:56.841534 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: FlushMRSOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.145s	user 0.108s	sys 0.028s Metrics: {"bytes_written":12307491,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":60,"dirs.run_cpu_time_us":202,"dirs.run_wall_time_us":690,"drs_written":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4,"lbm_write_time_us":35676,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:19:56.842124 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling LogGCOp(2f18854b61f24c9988d39c053b7131c4): free 20743880 bytes of WAL
I20260812 06:19:56.842324 29772 log_reader.cc:385] T 2f18854b61f24c9988d39c053b7131c4: removed 2 log segments from log reader
I20260812 06:19:56.842396 29772 log.cc:1079] T 2f18854b61f24c9988d39c053b7131c4 P 4ed50b40d9a947ae95122281383b2955: Deleting log segment in path: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591159890-29244-0/minicluster-data/ts-0-root/wals/2f18854b61f24c9988d39c053b7131c4/wal-000000001 (ops 1-6)
I20260812 06:19:56.842473 29772 log.cc:1079] T 2f18854b61f24c9988d39c053b7131c4 P 4ed50b40d9a947ae95122281383b2955: Deleting log segment in path: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591159890-29244-0/minicluster-data/ts-0-root/wals/2f18854b61f24c9988d39c053b7131c4/wal-000000002 (ops 7-11)
I20260812 06:19:56.847146 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: LogGCOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.005s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:19:56.847420 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4): perf score=2.188937
I20260812 06:19:56.861526 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.014s	user 0.004s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4792,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:56.861936 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling UndoDeltaBlockGCOp(2f18854b61f24c9988d39c053b7131c4): 16411393 bytes on disk
I20260812 06:19:56.862305 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: UndoDeltaBlockGCOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4}
I20260812 06:19:56.862733 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling MajorDeltaCompactionOp(2f18854b61f24c9988d39c053b7131c4): perf score=1.000000
I20260812 06:19:57.004801 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: MajorDeltaCompactionOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.142s	user 0.102s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":533,"lbm_read_time_us":9823,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24811,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"thread_start_us":295,"threads_started":5,"update_count":2000}
I20260812 06:19:57.005416 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4): perf score=14.095187
I20260812 06:19:57.048123 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.042s	user 0.033s	sys 0.007s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19286,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:57.048686 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4): perf score=2.188937
I20260812 06:19:57.064706 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.016s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5903,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:57.065310 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling MajorDeltaCompactionOp(2f18854b61f24c9988d39c053b7131c4): perf score=1.000000
I20260812 06:19:57.226296 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: MajorDeltaCompactionOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.161s	user 0.132s	sys 0.024s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":818,"lbm_read_time_us":9445,"lbm_reads_lt_1ms":564,"lbm_write_time_us":31367,"lbm_writes_lt_1ms":543,"mutex_wait_us":326,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":27264,"update_count":2500}
I20260812 06:19:57.226820 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4): perf score=10.126437
I20260812 06:19:57.264365 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.037s	user 0.019s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13334,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:57.264894 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4): perf score=2.188937
I20260812 06:19:57.279666 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.015s	user 0.012s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5669,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:57.280113 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling MajorDeltaCompactionOp(2f18854b61f24c9988d39c053b7131c4): perf score=1.000000
I20260812 06:19:57.405500 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: MajorDeltaCompactionOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.125s	user 0.099s	sys 0.025s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":662,"lbm_read_time_us":8295,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22127,"lbm_writes_lt_1ms":443,"mutex_wait_us":274,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6400,"update_count":2000}
I20260812 06:19:57.406026 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4): perf score=10.126437
I20260812 06:19:57.453604 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.047s	user 0.009s	sys 0.035s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":17932,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:57.454031 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4): perf score=2.188937
I20260812 06:19:57.463474 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3711,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:57.463790 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling MajorDeltaCompactionOp(2f18854b61f24c9988d39c053b7131c4): perf score=1.000000
I20260812 06:19:57.626639 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: MajorDeltaCompactionOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.163s	user 0.108s	sys 0.053s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":515,"lbm_read_time_us":10299,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26588,"lbm_writes_lt_1ms":443,"mutex_wait_us":271,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:57.627117 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4): perf score=10.126437
I20260812 06:19:57.676244 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.049s	user 0.026s	sys 0.010s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16789,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:57.676745 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4): perf score=2.188937
I20260812 06:19:57.686462 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3760,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:57.686786 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling MajorDeltaCompactionOp(2f18854b61f24c9988d39c053b7131c4): perf score=1.000000
I20260812 06:19:57.819795 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: MajorDeltaCompactionOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.133s	user 0.108s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":930,"lbm_read_time_us":8505,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26144,"lbm_writes_lt_1ms":443,"mutex_wait_us":720,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:19:57.820514 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4): perf score=10.126437
I20260812 06:19:57.862390 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.041s	user 0.030s	sys 0.011s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18201,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:57.862849 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4): perf score=2.188937
I20260812 06:19:57.872087 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3583,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:57.872424 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling MajorDeltaCompactionOp(2f18854b61f24c9988d39c053b7131c4): perf score=1.000000
I20260812 06:19:57.997676 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: MajorDeltaCompactionOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.125s	user 0.095s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1241,"lbm_read_time_us":8763,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22381,"lbm_writes_lt_1ms":443,"mutex_wait_us":476,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7424,"update_count":2000}
I20260812 06:19:57.998672 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4): perf score=10.126437
I20260812 06:19:58.043864 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.044s	user 0.021s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16800,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:58.044380 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4): perf score=2.188937
I20260812 06:19:58.056854 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.012s	user 0.000s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5050,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:58.057327 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling FlushMRSOp(2f18854b61f24c9988d39c053b7131c4): perf score=1.000000
I20260812 06:19:58.090536 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: FlushMRSOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.033s	user 0.033s	sys 0.000s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":55,"dirs.run_cpu_time_us":212,"dirs.run_wall_time_us":978,"drs_written":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1730,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:19:58.091131 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling LogGCOp(2f18854b61f24c9988d39c053b7131c4): free 120553376 bytes of WAL
I20260812 06:19:58.091336 29772 log_reader.cc:385] T 2f18854b61f24c9988d39c053b7131c4: removed 12 log segments from log reader
I20260812 06:19:58.091379 29772 log.cc:1079] T 2f18854b61f24c9988d39c053b7131c4 P 4ed50b40d9a947ae95122281383b2955: Deleting log segment in path: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591159890-29244-0/minicluster-data/ts-0-root/wals/2f18854b61f24c9988d39c053b7131c4/wal-000000003 (ops 12-16)
I20260812 06:19:58.091413 29772 log.cc:1079] T 2f18854b61f24c9988d39c053b7131c4 P 4ed50b40d9a947ae95122281383b2955: Deleting log segment in path: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591159890-29244-0/minicluster-data/ts-0-root/wals/2f18854b61f24c9988d39c053b7131c4/wal-000000004 (ops 17-21)
I20260812 06:19:58.091490 29772 log.cc:1079] T 2f18854b61f24c9988d39c053b7131c4 P 4ed50b40d9a947ae95122281383b2955: Deleting log segment in path: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591159890-29244-0/minicluster-data/ts-0-root/wals/2f18854b61f24c9988d39c053b7131c4/wal-000000005 (ops 22-26)
I20260812 06:19:58.091542 29772 log.cc:1079] T 2f18854b61f24c9988d39c053b7131c4 P 4ed50b40d9a947ae95122281383b2955: Deleting log segment in path: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591159890-29244-0/minicluster-data/ts-0-root/wals/2f18854b61f24c9988d39c053b7131c4/wal-000000006 (ops 27-31)
I20260812 06:19:58.091576 29772 log.cc:1079] T 2f18854b61f24c9988d39c053b7131c4 P 4ed50b40d9a947ae95122281383b2955: Deleting log segment in path: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591159890-29244-0/minicluster-data/ts-0-root/wals/2f18854b61f24c9988d39c053b7131c4/wal-000000007 (ops 32-36)
I20260812 06:19:58.091598 29772 log.cc:1079] T 2f18854b61f24c9988d39c053b7131c4 P 4ed50b40d9a947ae95122281383b2955: Deleting log segment in path: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591159890-29244-0/minicluster-data/ts-0-root/wals/2f18854b61f24c9988d39c053b7131c4/wal-000000008 (ops 37-41)
I20260812 06:19:58.091638 29772 log.cc:1079] T 2f18854b61f24c9988d39c053b7131c4 P 4ed50b40d9a947ae95122281383b2955: Deleting log segment in path: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591159890-29244-0/minicluster-data/ts-0-root/wals/2f18854b61f24c9988d39c053b7131c4/wal-000000009 (ops 42-46)
I20260812 06:19:58.091668 29772 log.cc:1079] T 2f18854b61f24c9988d39c053b7131c4 P 4ed50b40d9a947ae95122281383b2955: Deleting log segment in path: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591159890-29244-0/minicluster-data/ts-0-root/wals/2f18854b61f24c9988d39c053b7131c4/wal-000000010 (ops 47-50)
I20260812 06:19:58.091688 29772 log.cc:1079] T 2f18854b61f24c9988d39c053b7131c4 P 4ed50b40d9a947ae95122281383b2955: Deleting log segment in path: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591159890-29244-0/minicluster-data/ts-0-root/wals/2f18854b61f24c9988d39c053b7131c4/wal-000000011 (ops 51-55)
I20260812 06:19:58.091745 29772 log.cc:1079] T 2f18854b61f24c9988d39c053b7131c4 P 4ed50b40d9a947ae95122281383b2955: Deleting log segment in path: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591159890-29244-0/minicluster-data/ts-0-root/wals/2f18854b61f24c9988d39c053b7131c4/wal-000000012 (ops 56-60)
I20260812 06:19:58.091779 29772 log.cc:1079] T 2f18854b61f24c9988d39c053b7131c4 P 4ed50b40d9a947ae95122281383b2955: Deleting log segment in path: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591159890-29244-0/minicluster-data/ts-0-root/wals/2f18854b61f24c9988d39c053b7131c4/wal-000000013 (ops 61-64)
I20260812 06:19:58.091799 29772 log.cc:1079] T 2f18854b61f24c9988d39c053b7131c4 P 4ed50b40d9a947ae95122281383b2955: Deleting log segment in path: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591159890-29244-0/minicluster-data/ts-0-root/wals/2f18854b61f24c9988d39c053b7131c4/wal-000000014 (ops 65-69)
I20260812 06:19:58.117520 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: LogGCOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.026s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:19:58.117870 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4): perf score=6.157687
I20260812 06:19:58.148384 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.030s	user 0.012s	sys 0.009s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":9749,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:19:58.148873 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling UndoDeltaBlockGCOp(2f18854b61f24c9988d39c053b7131c4): 462 bytes on disk
I20260812 06:19:58.149251 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: UndoDeltaBlockGCOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4}
I20260812 06:19:58.149712 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling MajorDeltaCompactionOp(2f18854b61f24c9988d39c053b7131c4): perf score=1.000000
I20260812 06:19:58.349520 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: MajorDeltaCompactionOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.200s	user 0.141s	sys 0.046s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877221,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":280,"dirs.run_cpu_time_us":1133,"dirs.run_wall_time_us":6573,"lbm_read_time_us":13124,"lbm_reads_lt_1ms":665,"lbm_write_time_us":36206,"lbm_writes_lt_1ms":643,"mutex_wait_us":44,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":63104,"update_count":3000}
I20260812 06:19:58.350683 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4): perf score=18.063937
I20260812 06:19:58.405915 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.055s	user 0.036s	sys 0.015s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":24747,"lbm_writes_lt_1ms":503,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":2500}
I20260812 06:19:58.406669 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4): perf score=2.188937
I20260812 06:19:58.420109 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.013s	user 0.010s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5128,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:58.420502 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling MajorDeltaCompactionOp(2f18854b61f24c9988d39c053b7131c4): perf score=1.000000
I20260812 06:19:58.588240 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: MajorDeltaCompactionOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.168s	user 0.138s	sys 0.028s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877103,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":910,"lbm_read_time_us":9615,"lbm_reads_lt_1ms":664,"lbm_write_time_us":35231,"lbm_writes_lt_1ms":643,"mutex_wait_us":285,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":21376,"thread_start_us":89,"threads_started":1,"update_count":3000}
I20260812 06:19:58.588766 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4): perf score=14.095187
I20260812 06:19:58.640022 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.051s	user 0.024s	sys 0.024s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23420,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:58.640465 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4): perf score=2.188937
I20260812 06:19:58.653905 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5073,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:58.654467 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling MajorDeltaCompactionOp(2f18854b61f24c9988d39c053b7131c4): perf score=1.000000
I20260812 06:19:58.791688 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: MajorDeltaCompactionOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.137s	user 0.107s	sys 0.030s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":617,"lbm_read_time_us":8449,"lbm_reads_lt_1ms":564,"lbm_write_time_us":25316,"lbm_writes_lt_1ms":543,"mutex_wait_us":20,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9216,"update_count":2500}
I20260812 06:19:58.792199 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4): perf score=10.126437
I20260812 06:19:58.829272 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.037s	user 0.013s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15271,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:58.829970 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling MajorDeltaCompactionOp(2f18854b61f24c9988d39c053b7131c4): perf score=1.000000
I20260812 06:19:58.958058 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: MajorDeltaCompactionOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.128s	user 0.072s	sys 0.052s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569746,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":805,"lbm_read_time_us":8264,"lbm_reads_lt_1ms":367,"lbm_write_time_us":20340,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":342,"mutex_wait_us":274,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":9344,"update_count":1500}
I20260812 06:19:58.958564 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4): perf score=10.126437
I20260812 06:19:59.006538 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.048s	user 0.024s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16533,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:59.006923 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4): perf score=2.188937
I20260812 06:19:59.016314 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3641,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:59.016641 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling MajorDeltaCompactionOp(2f18854b61f24c9988d39c053b7131c4): perf score=1.000000
I20260812 06:19:59.162743 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: MajorDeltaCompactionOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.146s	user 0.111s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":529,"lbm_read_time_us":8848,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22946,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3840,"update_count":2000}
I20260812 06:19:59.163343 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4): perf score=10.126437
I20260812 06:19:59.209429 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.046s	user 0.016s	sys 0.017s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16177,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:59.209828 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4): perf score=2.188937
I20260812 06:19:59.219409 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3690,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:59.219794 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling MajorDeltaCompactionOp(2f18854b61f24c9988d39c053b7131c4): perf score=1.000000
I20260812 06:19:59.356719 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: MajorDeltaCompactionOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.137s	user 0.097s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":447,"lbm_read_time_us":8737,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24262,"lbm_writes_lt_1ms":443,"mutex_wait_us":3,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:59.357225 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4): perf score=10.126437
I20260812 06:19:59.411989 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.055s	user 0.027s	sys 0.018s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18425,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:59.412484 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4): perf score=2.188937
I20260812 06:19:59.422461 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3818,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:59.422878 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling FlushMRSOp(2f18854b61f24c9988d39c053b7131c4): perf score=1.000000
I20260812 06:19:59.449431 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: FlushMRSOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.026s	user 0.025s	sys 0.000s Metrics: {"bytes_written":1152514,"cfile_init":1,"dirs.queue_time_us":38,"dirs.run_cpu_time_us":158,"dirs.run_wall_time_us":2284,"drs_written":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1806,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:59.450035 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling LogGCOp(2f18854b61f24c9988d39c053b7131c4): free 112692371 bytes of WAL
I20260812 06:19:59.450237 29772 log_reader.cc:385] T 2f18854b61f24c9988d39c053b7131c4: removed 11 log segments from log reader
I20260812 06:19:59.450280 29772 log.cc:1079] T 2f18854b61f24c9988d39c053b7131c4 P 4ed50b40d9a947ae95122281383b2955: Deleting log segment in path: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591159890-29244-0/minicluster-data/ts-0-root/wals/2f18854b61f24c9988d39c053b7131c4/wal-000000015 (ops 70-74)
I20260812 06:19:59.450387 29772 log.cc:1079] T 2f18854b61f24c9988d39c053b7131c4 P 4ed50b40d9a947ae95122281383b2955: Deleting log segment in path: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591159890-29244-0/minicluster-data/ts-0-root/wals/2f18854b61f24c9988d39c053b7131c4/wal-000000016 (ops 75-79)
I20260812 06:19:59.450426 29772 log.cc:1079] T 2f18854b61f24c9988d39c053b7131c4 P 4ed50b40d9a947ae95122281383b2955: Deleting log segment in path: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591159890-29244-0/minicluster-data/ts-0-root/wals/2f18854b61f24c9988d39c053b7131c4/wal-000000017 (ops 80-84)
I20260812 06:19:59.450453 29772 log.cc:1079] T 2f18854b61f24c9988d39c053b7131c4 P 4ed50b40d9a947ae95122281383b2955: Deleting log segment in path: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591159890-29244-0/minicluster-data/ts-0-root/wals/2f18854b61f24c9988d39c053b7131c4/wal-000000018 (ops 85-89)
I20260812 06:19:59.450511 29772 log.cc:1079] T 2f18854b61f24c9988d39c053b7131c4 P 4ed50b40d9a947ae95122281383b2955: Deleting log segment in path: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591159890-29244-0/minicluster-data/ts-0-root/wals/2f18854b61f24c9988d39c053b7131c4/wal-000000019 (ops 90-94)
I20260812 06:19:59.450548 29772 log.cc:1079] T 2f18854b61f24c9988d39c053b7131c4 P 4ed50b40d9a947ae95122281383b2955: Deleting log segment in path: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591159890-29244-0/minicluster-data/ts-0-root/wals/2f18854b61f24c9988d39c053b7131c4/wal-000000020 (ops 95-99)
I20260812 06:19:59.450573 29772 log.cc:1079] T 2f18854b61f24c9988d39c053b7131c4 P 4ed50b40d9a947ae95122281383b2955: Deleting log segment in path: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591159890-29244-0/minicluster-data/ts-0-root/wals/2f18854b61f24c9988d39c053b7131c4/wal-000000021 (ops 100-104)
I20260812 06:19:59.450639 29772 log.cc:1079] T 2f18854b61f24c9988d39c053b7131c4 P 4ed50b40d9a947ae95122281383b2955: Deleting log segment in path: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591159890-29244-0/minicluster-data/ts-0-root/wals/2f18854b61f24c9988d39c053b7131c4/wal-000000022 (ops 105-109)
I20260812 06:19:59.450675 29772 log.cc:1079] T 2f18854b61f24c9988d39c053b7131c4 P 4ed50b40d9a947ae95122281383b2955: Deleting log segment in path: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591159890-29244-0/minicluster-data/ts-0-root/wals/2f18854b61f24c9988d39c053b7131c4/wal-000000023 (ops 110-114)
I20260812 06:19:59.450730 29772 log.cc:1079] T 2f18854b61f24c9988d39c053b7131c4 P 4ed50b40d9a947ae95122281383b2955: Deleting log segment in path: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591159890-29244-0/minicluster-data/ts-0-root/wals/2f18854b61f24c9988d39c053b7131c4/wal-000000024 (ops 115-119)
I20260812 06:19:59.450765 29772 log.cc:1079] T 2f18854b61f24c9988d39c053b7131c4 P 4ed50b40d9a947ae95122281383b2955: Deleting log segment in path: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591159890-29244-0/minicluster-data/ts-0-root/wals/2f18854b61f24c9988d39c053b7131c4/wal-000000025 (ops 120-124)
I20260812 06:19:59.470369 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: LogGCOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.020s	user 0.001s	sys 0.015s Metrics: {}
I20260812 06:19:59.470700 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4): perf score=1.196750
I20260812 06:19:59.479260 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.008s	user 0.003s	sys 0.005s Metrics: {"bytes_written":2953959,"delete_count":0,"lbm_write_time_us":2913,"lbm_writes_lt_1ms":75,"reinsert_count":0,"update_count":360}
I20260812 06:19:59.479665 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling UndoDeltaBlockGCOp(2f18854b61f24c9988d39c053b7131c4): 447 bytes on disk
I20260812 06:19:59.480043 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: UndoDeltaBlockGCOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4}
I20260812 06:19:59.480530 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4): perf score=1.000000
I20260812 06:19:59.486069 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.005s	user 0.000s	sys 0.004s Metrics: {"bytes_written":1148852,"delete_count":0,"lbm_write_time_us":1611,"lbm_writes_lt_1ms":31,"reinsert_count":0,"update_count":140}
I20260812 06:19:59.486615 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling MajorDeltaCompactionOp(2f18854b61f24c9988d39c053b7131c4): perf score=1.000000
I20260812 06:19:59.679735 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: MajorDeltaCompactionOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.193s	user 0.147s	sys 0.044s Metrics: {"cfile_cache_miss":534,"cfile_cache_miss_bytes":24774833,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":443,"lbm_read_time_us":13912,"lbm_reads_lt_1ms":574,"lbm_write_time_us":33538,"lbm_writes_lt_1ms":543,"mutex_wait_us":227,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":71,"threads_started":1,"update_count":2500}
I20260812 06:19:59.680272 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4): perf score=11.118625
I20260812 06:19:59.729086 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.049s	user 0.023s	sys 0.018s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16277,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:59.729523 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4): perf score=3.181125
I20260812 06:19:59.746454 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.017s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4471878,"delete_count":0,"lbm_write_time_us":6550,"lbm_writes_lt_1ms":112,"reinsert_count":0,"update_count":545}
I20260812 06:19:59.746836 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4): perf score=2.188937
I20260812 06:19:59.758674 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.012s	user 0.004s	sys 0.008s Metrics: {"bytes_written":3323180,"delete_count":0,"lbm_write_time_us":4314,"lbm_writes_lt_1ms":84,"reinsert_count":0,"update_count":405}
I20260812 06:19:59.759065 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling MajorDeltaCompactionOp(2f18854b61f24c9988d39c053b7131c4): perf score=1.000000
I20260812 06:19:59.918365 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: MajorDeltaCompactionOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.159s	user 0.106s	sys 0.052s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774793,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":548,"lbm_read_time_us":13730,"lbm_reads_lt_1ms":573,"lbm_write_time_us":25792,"lbm_writes_lt_1ms":543,"mutex_wait_us":76,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13440,"update_count":2500}
I20260812 06:19:59.919982 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4): perf score=10.126437
I20260812 06:19:59.963647 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.043s	user 0.028s	sys 0.003s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13785,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:59.964051 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4): perf score=2.188937
I20260812 06:19:59.987787 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.024s	user 0.011s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5427,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:59.988206 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling MajorDeltaCompactionOp(2f18854b61f24c9988d39c053b7131c4): perf score=1.000000
I20260812 06:20:00.147029 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: MajorDeltaCompactionOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.159s	user 0.111s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":476,"lbm_read_time_us":11381,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23696,"lbm_writes_lt_1ms":443,"mutex_wait_us":260,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:20:00.147619 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4): perf score=10.126437
I20260812 06:20:00.197077 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.049s	user 0.022s	sys 0.012s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16948,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:00.197482 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4): perf score=2.188937
I20260812 06:20:00.207037 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.009s	user 0.007s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3739,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:00.207383 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling MajorDeltaCompactionOp(2f18854b61f24c9988d39c053b7131c4): perf score=1.000000
I20260812 06:20:00.354097 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: MajorDeltaCompactionOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.147s	user 0.099s	sys 0.038s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":740,"lbm_read_time_us":9448,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28624,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":28,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10112,"update_count":2000}
I20260812 06:20:00.354693 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4): perf score=10.126437
I20260812 06:20:00.399847 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.043s	user 0.032s	sys 0.003s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16399,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:00.400317 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4): perf score=2.188937
I20260812 06:20:00.414829 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.014s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5773,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:00.415359 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling MajorDeltaCompactionOp(2f18854b61f24c9988d39c053b7131c4): perf score=1.000000
I20260812 06:20:00.547235 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: MajorDeltaCompactionOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.132s	user 0.100s	sys 0.029s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":507,"lbm_read_time_us":9941,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26259,"lbm_writes_lt_1ms":443,"mutex_wait_us":300,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10880,"update_count":2000}
I20260812 06:20:00.547919 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4): perf score=11.118625
I20260812 06:20:00.589869 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.040s	user 0.022s	sys 0.015s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":13345,"lbm_writes_lt_1ms":313,"reinsert_count":0,"spinlock_wait_cycles":4992,"update_count":1550}
I20260812 06:20:00.590276 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4): perf score=2.188937
I20260812 06:20:00.599037 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.009s	user 0.006s	sys 0.002s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3297,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:00.599409 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling MajorDeltaCompactionOp(2f18854b61f24c9988d39c053b7131c4): perf score=1.000000
I20260812 06:20:00.774080 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: MajorDeltaCompactionOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.175s	user 0.089s	sys 0.070s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672270,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":4058,"dirs.run_cpu_time_us":1504,"dirs.run_wall_time_us":8746,"lbm_read_time_us":11785,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24879,"lbm_writes_lt_1ms":443,"mutex_wait_us":3384,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11648,"update_count":2000}
I20260812 06:20:00.774677 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4): perf score=10.126437
I20260812 06:20:00.820503 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.046s	user 0.015s	sys 0.019s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16409,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:00.821008 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4): perf score=2.188937
I20260812 06:20:00.834885 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.014s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5383,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:00.835358 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling MajorDeltaCompactionOp(2f18854b61f24c9988d39c053b7131c4): perf score=1.000000
I20260812 06:20:00.957530 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: MajorDeltaCompactionOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.122s	user 0.087s	sys 0.025s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":198,"lbm_read_time_us":7649,"lbm_reads_lt_1ms":468,"lbm_write_time_us":21241,"lbm_writes_lt_1ms":443,"mutex_wait_us":87,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:20:00.958094 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4): perf score=10.126437
I20260812 06:20:01.005838 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.047s	user 0.021s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15832,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:01.006305 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4): perf score=2.188937
I20260812 06:20:01.021477 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.015s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5435,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:01.022166 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling FlushMRSOp(2f18854b61f24c9988d39c053b7131c4): perf score=1.000000
I20260812 06:20:01.058126 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: FlushMRSOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.034s	user 0.026s	sys 0.003s Metrics: {"bytes_written":1234475,"cfile_init":1,"dirs.queue_time_us":56,"dirs.run_cpu_time_us":213,"dirs.run_wall_time_us":972,"drs_written":1,"lbm_read_time_us":41,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1478,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:20:01.059015 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling LogGCOp(2f18854b61f24c9988d39c053b7131c4): free 124710561 bytes of WAL
I20260812 06:20:01.059312 29772 log_reader.cc:385] T 2f18854b61f24c9988d39c053b7131c4: removed 12 log segments from log reader
I20260812 06:20:01.059369 29772 log.cc:1079] T 2f18854b61f24c9988d39c053b7131c4 P 4ed50b40d9a947ae95122281383b2955: Deleting log segment in path: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591159890-29244-0/minicluster-data/ts-0-root/wals/2f18854b61f24c9988d39c053b7131c4/wal-000000026 (ops 125-129)
I20260812 06:20:01.059401 29772 log.cc:1079] T 2f18854b61f24c9988d39c053b7131c4 P 4ed50b40d9a947ae95122281383b2955: Deleting log segment in path: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591159890-29244-0/minicluster-data/ts-0-root/wals/2f18854b61f24c9988d39c053b7131c4/wal-000000027 (ops 130-134)
I20260812 06:20:01.059422 29772 log.cc:1079] T 2f18854b61f24c9988d39c053b7131c4 P 4ed50b40d9a947ae95122281383b2955: Deleting log segment in path: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591159890-29244-0/minicluster-data/ts-0-root/wals/2f18854b61f24c9988d39c053b7131c4/wal-000000028 (ops 135-139)
I20260812 06:20:01.059471 29772 log.cc:1079] T 2f18854b61f24c9988d39c053b7131c4 P 4ed50b40d9a947ae95122281383b2955: Deleting log segment in path: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591159890-29244-0/minicluster-data/ts-0-root/wals/2f18854b61f24c9988d39c053b7131c4/wal-000000029 (ops 140-144)
I20260812 06:20:01.059502 29772 log.cc:1079] T 2f18854b61f24c9988d39c053b7131c4 P 4ed50b40d9a947ae95122281383b2955: Deleting log segment in path: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591159890-29244-0/minicluster-data/ts-0-root/wals/2f18854b61f24c9988d39c053b7131c4/wal-000000030 (ops 145-149)
I20260812 06:20:01.059544 29772 log.cc:1079] T 2f18854b61f24c9988d39c053b7131c4 P 4ed50b40d9a947ae95122281383b2955: Deleting log segment in path: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591159890-29244-0/minicluster-data/ts-0-root/wals/2f18854b61f24c9988d39c053b7131c4/wal-000000031 (ops 150-154)
I20260812 06:20:01.059573 29772 log.cc:1079] T 2f18854b61f24c9988d39c053b7131c4 P 4ed50b40d9a947ae95122281383b2955: Deleting log segment in path: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591159890-29244-0/minicluster-data/ts-0-root/wals/2f18854b61f24c9988d39c053b7131c4/wal-000000032 (ops 155-159)
I20260812 06:20:01.059623 29772 log.cc:1079] T 2f18854b61f24c9988d39c053b7131c4 P 4ed50b40d9a947ae95122281383b2955: Deleting log segment in path: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591159890-29244-0/minicluster-data/ts-0-root/wals/2f18854b61f24c9988d39c053b7131c4/wal-000000033 (ops 160-164)
I20260812 06:20:01.059653 29772 log.cc:1079] T 2f18854b61f24c9988d39c053b7131c4 P 4ed50b40d9a947ae95122281383b2955: Deleting log segment in path: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591159890-29244-0/minicluster-data/ts-0-root/wals/2f18854b61f24c9988d39c053b7131c4/wal-000000034 (ops 165-169)
I20260812 06:20:01.059705 29772 log.cc:1079] T 2f18854b61f24c9988d39c053b7131c4 P 4ed50b40d9a947ae95122281383b2955: Deleting log segment in path: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591159890-29244-0/minicluster-data/ts-0-root/wals/2f18854b61f24c9988d39c053b7131c4/wal-000000035 (ops 170-174)
I20260812 06:20:01.059736 29772 log.cc:1079] T 2f18854b61f24c9988d39c053b7131c4 P 4ed50b40d9a947ae95122281383b2955: Deleting log segment in path: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591159890-29244-0/minicluster-data/ts-0-root/wals/2f18854b61f24c9988d39c053b7131c4/wal-000000036 (ops 175-179)
I20260812 06:20:01.059774 29772 log.cc:1079] T 2f18854b61f24c9988d39c053b7131c4 P 4ed50b40d9a947ae95122281383b2955: Deleting log segment in path: /tmp/dist-test-taskmvY1K_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591159890-29244-0/minicluster-data/ts-0-root/wals/2f18854b61f24c9988d39c053b7131c4/wal-000000037 (ops 180-184)
I20260812 06:20:01.086869 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: LogGCOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.028s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:20:01.087416 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4): perf score=6.157687
I20260812 06:20:01.113169 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.026s	user 0.017s	sys 0.004s Metrics: {"bytes_written":8205077,"delete_count":0,"lbm_write_time_us":10081,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:20:01.113849 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling MajorDeltaCompactionOp(2f18854b61f24c9988d39c053b7131c4): perf score=1.000000
I20260812 06:20:01.288830 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: MajorDeltaCompactionOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.175s	user 0.154s	sys 0.019s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877220,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":131,"lbm_read_time_us":12961,"lbm_reads_lt_1ms":669,"lbm_write_time_us":33541,"lbm_writes_lt_1ms":643,"mutex_wait_us":29,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":11776,"thread_start_us":75,"threads_started":1,"update_count":3000}
I20260812 06:20:01.289454 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4): perf score=14.095187
I20260812 06:20:01.328841 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.037s	user 0.018s	sys 0.017s Metrics: {"bytes_written":16820143,"delete_count":0,"lbm_write_time_us":16567,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:20:01.329233 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4): perf score=2.188937
I20260812 06:20:01.343428 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: FlushDeltaMemStoresOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.014s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5406,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:01.343818 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling UndoDeltaBlockGCOp(2f18854b61f24c9988d39c053b7131c4): 472 bytes on disk
I20260812 06:20:01.344169 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: UndoDeltaBlockGCOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":45,"lbm_reads_lt_1ms":4}
I20260812 06:20:01.344645 29875 maintenance_manager.cc:419] P 4ed50b40d9a947ae95122281383b2955: Scheduling MajorDeltaCompactionOp(2f18854b61f24c9988d39c053b7131c4): perf score=1.000000
I20260812 06:20:01.411550 29244 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.869s	user 1.772s	sys 0.125s
I20260812 06:20:01.484186 29244 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.072s	user 0.001s	sys 0.000s
I20260812 06:20:01.484704 29244 tablet_server.cc:179] TabletServer@127.28.143.1:0 shutting down...
I20260812 06:20:01.496045 29772 maintenance_manager.cc:643] P 4ed50b40d9a947ae95122281383b2955: MajorDeltaCompactionOp(2f18854b61f24c9988d39c053b7131c4) complete. Timing: real 0.151s	user 0.135s	sys 0.016s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774676,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":124,"lbm_read_time_us":10380,"lbm_reads_lt_1ms":568,"lbm_write_time_us":29350,"lbm_writes_lt_1ms":543,"mutex_wait_us":20,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4864,"update_count":2500}
I20260812 06:20:01.498665 29244 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:20:01.498884 29244 tablet_replica.cc:333] T 2f18854b61f24c9988d39c053b7131c4 P 4ed50b40d9a947ae95122281383b2955: stopping tablet replica
I20260812 06:20:01.499003 29244 raft_consensus.cc:2243] T 2f18854b61f24c9988d39c053b7131c4 P 4ed50b40d9a947ae95122281383b2955 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:01.499145 29244 raft_consensus.cc:2272] T 2f18854b61f24c9988d39c053b7131c4 P 4ed50b40d9a947ae95122281383b2955 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:01.503793 29244 tablet_server.cc:196] TabletServer@127.28.143.1:0 shutdown complete.
I20260812 06:20:01.540370 29244 master.cc:562] Master@127.28.143.62:42547 shutting down...
I20260812 06:20:01.543820 29244 raft_consensus.cc:2243] T 00000000000000000000000000000000 P f11a004722db4f2799d2aa581015bd65 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:01.543970 29244 raft_consensus.cc:2272] T 00000000000000000000000000000000 P f11a004722db4f2799d2aa581015bd65 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:01.544034 29244 tablet_replica.cc:333] T 00000000000000000000000000000000 P f11a004722db4f2799d2aa581015bd65: stopping tablet replica
I20260812 06:20:01.556177 29244 master.cc:584] Master@127.28.143.62:42547 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5338 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10461 ms total)

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