[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:18:54.153112   757 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.0.189.126:41719
I20260812 06:18:54.154400   757 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:18:54.155493   757 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:54.163902   763 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:54.164012   766 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:54.164121   757 server_base.cc:1061] running on GCE node
W20260812 06:18:54.164528   764 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:54.165256   757 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:54.165413   757 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:54.165478   757 hybrid_clock.cc:648] HybridClock initialized: now 1786515534165475 us; error 0 us; skew 500 ppm
I20260812 06:18:54.167711   757 webserver.cc:533] Webserver started at http://127.0.189.126:45859/ using document root <none> and password file <none>
I20260812 06:18:54.168721   757 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:54.168838   757 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:54.169220   757 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:54.171221   757 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534140020-757-0/minicluster-data/master-0-root/instance:
uuid: "2589840e739147ee95725a534cfe8ea3"
format_stamp: "Formatted at 2026-08-12 06:18:54 on dist-test-slave-rgb1"
I20260812 06:18:54.177057   757 fs_manager.cc:696] Time spent creating directory manager: real 0.005s	user 0.007s	sys 0.000s
I20260812 06:18:54.179967   771 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:54.181885   757 fs_manager.cc:730] Time spent opening block manager: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:54.182111   757 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534140020-757-0/minicluster-data/master-0-root
uuid: "2589840e739147ee95725a534cfe8ea3"
format_stamp: "Formatted at 2026-08-12 06:18:54 on dist-test-slave-rgb1"
I20260812 06:18:54.182256   757 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534140020-757-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534140020-757-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534140020-757-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:54.195269   757 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:54.195976   757 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:18:54.196180   757 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:54.204648   757 rpc_server.cc:307] RPC server started. Bound to: 127.0.189.126:41719
I20260812 06:18:54.204710   830 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.0.189.126:41719 every 8 connection(s)
I20260812 06:18:54.207422   831 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:54.214124   831 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 2589840e739147ee95725a534cfe8ea3: Bootstrap starting.
I20260812 06:18:54.216949   831 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 2589840e739147ee95725a534cfe8ea3: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:54.218017   831 log.cc:826] T 00000000000000000000000000000000 P 2589840e739147ee95725a534cfe8ea3: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:54.220135   831 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 2589840e739147ee95725a534cfe8ea3: No bootstrap required, opened a new log
I20260812 06:18:54.223810   831 raft_consensus.cc:359] T 00000000000000000000000000000000 P 2589840e739147ee95725a534cfe8ea3 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2589840e739147ee95725a534cfe8ea3" member_type: VOTER }
I20260812 06:18:54.224038   831 raft_consensus.cc:385] T 00000000000000000000000000000000 P 2589840e739147ee95725a534cfe8ea3 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:54.224087   831 raft_consensus.cc:740] T 00000000000000000000000000000000 P 2589840e739147ee95725a534cfe8ea3 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 2589840e739147ee95725a534cfe8ea3, State: Initialized, Role: FOLLOWER
I20260812 06:18:54.224874   831 consensus_queue.cc:260] T 00000000000000000000000000000000 P 2589840e739147ee95725a534cfe8ea3 [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: "2589840e739147ee95725a534cfe8ea3" member_type: VOTER }
I20260812 06:18:54.225069   831 raft_consensus.cc:399] T 00000000000000000000000000000000 P 2589840e739147ee95725a534cfe8ea3 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:54.225121   831 raft_consensus.cc:493] T 00000000000000000000000000000000 P 2589840e739147ee95725a534cfe8ea3 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:54.225220   831 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 2589840e739147ee95725a534cfe8ea3 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:54.226195   831 raft_consensus.cc:515] T 00000000000000000000000000000000 P 2589840e739147ee95725a534cfe8ea3 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2589840e739147ee95725a534cfe8ea3" member_type: VOTER }
I20260812 06:18:54.226701   831 leader_election.cc:304] T 00000000000000000000000000000000 P 2589840e739147ee95725a534cfe8ea3 [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: 2589840e739147ee95725a534cfe8ea3; no voters: 
I20260812 06:18:54.227100   831 leader_election.cc:290] T 00000000000000000000000000000000 P 2589840e739147ee95725a534cfe8ea3 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:54.227241   835 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 2589840e739147ee95725a534cfe8ea3 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:54.227483   835 raft_consensus.cc:697] T 00000000000000000000000000000000 P 2589840e739147ee95725a534cfe8ea3 [term 1 LEADER]: Becoming Leader. State: Replica: 2589840e739147ee95725a534cfe8ea3, State: Running, Role: LEADER
I20260812 06:18:54.228377   835 consensus_queue.cc:237] T 00000000000000000000000000000000 P 2589840e739147ee95725a534cfe8ea3 [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: "2589840e739147ee95725a534cfe8ea3" member_type: VOTER }
I20260812 06:18:54.228796   831 sys_catalog.cc:565] T 00000000000000000000000000000000 P 2589840e739147ee95725a534cfe8ea3 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:54.231087   837 sys_catalog.cc:455] T 00000000000000000000000000000000 P 2589840e739147ee95725a534cfe8ea3 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 2589840e739147ee95725a534cfe8ea3. Latest consensus state: current_term: 1 leader_uuid: "2589840e739147ee95725a534cfe8ea3" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2589840e739147ee95725a534cfe8ea3" member_type: VOTER } }
I20260812 06:18:54.231123   836 sys_catalog.cc:455] T 00000000000000000000000000000000 P 2589840e739147ee95725a534cfe8ea3 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "2589840e739147ee95725a534cfe8ea3" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2589840e739147ee95725a534cfe8ea3" member_type: VOTER } }
I20260812 06:18:54.231228   837 sys_catalog.cc:458] T 00000000000000000000000000000000 P 2589840e739147ee95725a534cfe8ea3 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:54.231240   836 sys_catalog.cc:458] T 00000000000000000000000000000000 P 2589840e739147ee95725a534cfe8ea3 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:54.232231   846 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:54.232303   757 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:54.235208   846 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:54.241215   846 catalog_manager.cc:1383] Generated new cluster ID: 26e1ca571fff447d8821eaea5dc1c449
I20260812 06:18:54.241313   846 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:54.261994   846 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:54.263032   846 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:54.268944   846 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 2589840e739147ee95725a534cfe8ea3: Generated new TSK 0
I20260812 06:18:54.269640   846 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:54.297700   757 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:54.300935   856 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:54.301019   859 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:54.301231   861 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:54.301632   757 server_base.cc:1061] running on GCE node
I20260812 06:18:54.301879   757 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:54.301949   757 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:54.302053   757 hybrid_clock.cc:648] HybridClock initialized: now 1786515534301986 us; error 0 us; skew 500 ppm
I20260812 06:18:54.303190   757 webserver.cc:533] Webserver started at http://127.0.189.65:32929/ using document root <none> and password file <none>
I20260812 06:18:54.303399   757 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:54.303476   757 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:54.303560   757 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:54.303990   757 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534140020-757-0/minicluster-data/ts-0-root/instance:
uuid: "1afc727aadf348d6ac7aaba592f9cbda"
format_stamp: "Formatted at 2026-08-12 06:18:54 on dist-test-slave-rgb1"
I20260812 06:18:54.305678   757 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:18:54.306746   867 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:54.307010   757 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:54.307085   757 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534140020-757-0/minicluster-data/ts-0-root
uuid: "1afc727aadf348d6ac7aaba592f9cbda"
format_stamp: "Formatted at 2026-08-12 06:18:54 on dist-test-slave-rgb1"
I20260812 06:18:54.307178   757 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534140020-757-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534140020-757-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534140020-757-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:54.319978   757 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:54.320508   757 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:54.321584   757 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:54.323117   757 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:54.323184   757 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:54.323274   757 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:54.323320   757 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:54.331210   757 rpc_server.cc:307] RPC server started. Bound to: 127.0.189.65:39009
I20260812 06:18:54.331226   942 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.0.189.65:39009 every 8 connection(s)
I20260812 06:18:54.343744   943 heartbeater.cc:344] Connected to a master server at 127.0.189.126:41719
I20260812 06:18:54.344090   943 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:54.344868   943 heartbeater.cc:507] Master 127.0.189.126:41719 requested a full tablet report, sending...
I20260812 06:18:54.347074   792 ts_manager.cc:194] Registered new tserver with Master: 1afc727aadf348d6ac7aaba592f9cbda (127.0.189.65:39009)
I20260812 06:18:54.347355   757 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.015398364s
I20260812 06:18:54.348493   792 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:46412
I20260812 06:18:54.359485   792 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:46418:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:54.377138   900 tablet_service.cc:1511] Processing CreateTablet for tablet 1a99d49b34a941f0aef21f4f17173b8b (DEFAULT_TABLE table=heavy-update-compaction-test [id=49dd490e19f1428eb091d63af53f4a3b]), partition=
I20260812 06:18:54.377751   900 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 1a99d49b34a941f0aef21f4f17173b8b. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:54.380820   955 tablet_bootstrap.cc:492] T 1a99d49b34a941f0aef21f4f17173b8b P 1afc727aadf348d6ac7aaba592f9cbda: Bootstrap starting.
I20260812 06:18:54.382081   955 tablet_bootstrap.cc:654] T 1a99d49b34a941f0aef21f4f17173b8b P 1afc727aadf348d6ac7aaba592f9cbda: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:54.384187   955 tablet_bootstrap.cc:492] T 1a99d49b34a941f0aef21f4f17173b8b P 1afc727aadf348d6ac7aaba592f9cbda: No bootstrap required, opened a new log
I20260812 06:18:54.384339   955 ts_tablet_manager.cc:1403] T 1a99d49b34a941f0aef21f4f17173b8b P 1afc727aadf348d6ac7aaba592f9cbda: Time spent bootstrapping tablet: real 0.004s	user 0.002s	sys 0.000s
I20260812 06:18:54.385267   955 raft_consensus.cc:359] T 1a99d49b34a941f0aef21f4f17173b8b P 1afc727aadf348d6ac7aaba592f9cbda [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1afc727aadf348d6ac7aaba592f9cbda" member_type: VOTER last_known_addr { host: "127.0.189.65" port: 39009 } }
I20260812 06:18:54.385535   955 raft_consensus.cc:385] T 1a99d49b34a941f0aef21f4f17173b8b P 1afc727aadf348d6ac7aaba592f9cbda [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:54.385648   955 raft_consensus.cc:740] T 1a99d49b34a941f0aef21f4f17173b8b P 1afc727aadf348d6ac7aaba592f9cbda [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 1afc727aadf348d6ac7aaba592f9cbda, State: Initialized, Role: FOLLOWER
I20260812 06:18:54.385902   955 consensus_queue.cc:260] T 1a99d49b34a941f0aef21f4f17173b8b P 1afc727aadf348d6ac7aaba592f9cbda [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: "1afc727aadf348d6ac7aaba592f9cbda" member_type: VOTER last_known_addr { host: "127.0.189.65" port: 39009 } }
I20260812 06:18:54.386031   955 raft_consensus.cc:399] T 1a99d49b34a941f0aef21f4f17173b8b P 1afc727aadf348d6ac7aaba592f9cbda [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:54.386144   955 raft_consensus.cc:493] T 1a99d49b34a941f0aef21f4f17173b8b P 1afc727aadf348d6ac7aaba592f9cbda [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:54.386230   955 raft_consensus.cc:3060] T 1a99d49b34a941f0aef21f4f17173b8b P 1afc727aadf348d6ac7aaba592f9cbda [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:54.387696   955 raft_consensus.cc:515] T 1a99d49b34a941f0aef21f4f17173b8b P 1afc727aadf348d6ac7aaba592f9cbda [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1afc727aadf348d6ac7aaba592f9cbda" member_type: VOTER last_known_addr { host: "127.0.189.65" port: 39009 } }
I20260812 06:18:54.387889   955 leader_election.cc:304] T 1a99d49b34a941f0aef21f4f17173b8b P 1afc727aadf348d6ac7aaba592f9cbda [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: 1afc727aadf348d6ac7aaba592f9cbda; no voters: 
I20260812 06:18:54.388181   955 leader_election.cc:290] T 1a99d49b34a941f0aef21f4f17173b8b P 1afc727aadf348d6ac7aaba592f9cbda [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:54.388334   957 raft_consensus.cc:2804] T 1a99d49b34a941f0aef21f4f17173b8b P 1afc727aadf348d6ac7aaba592f9cbda [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:54.388753   957 raft_consensus.cc:697] T 1a99d49b34a941f0aef21f4f17173b8b P 1afc727aadf348d6ac7aaba592f9cbda [term 1 LEADER]: Becoming Leader. State: Replica: 1afc727aadf348d6ac7aaba592f9cbda, State: Running, Role: LEADER
I20260812 06:18:54.388855   955 ts_tablet_manager.cc:1434] T 1a99d49b34a941f0aef21f4f17173b8b P 1afc727aadf348d6ac7aaba592f9cbda: Time spent starting tablet: real 0.004s	user 0.000s	sys 0.003s
I20260812 06:18:54.388998   957 consensus_queue.cc:237] T 1a99d49b34a941f0aef21f4f17173b8b P 1afc727aadf348d6ac7aaba592f9cbda [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: "1afc727aadf348d6ac7aaba592f9cbda" member_type: VOTER last_known_addr { host: "127.0.189.65" port: 39009 } }
I20260812 06:18:54.389546   943 heartbeater.cc:499] Master 127.0.189.126:41719 was elected leader, sending a full tablet report...
I20260812 06:18:54.393036   792 catalog_manager.cc:5719] T 1a99d49b34a941f0aef21f4f17173b8b P 1afc727aadf348d6ac7aaba592f9cbda reported cstate change: term changed from 0 to 1, leader changed from <none> to 1afc727aadf348d6ac7aaba592f9cbda (127.0.189.65). New cstate: current_term: 1 leader_uuid: "1afc727aadf348d6ac7aaba592f9cbda" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1afc727aadf348d6ac7aaba592f9cbda" member_type: VOTER last_known_addr { host: "127.0.189.65" port: 39009 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:54.485283   757 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.076s	user 0.020s	sys 0.013s
I20260812 06:18:54.582738   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling FlushMRSOp(1a99d49b34a941f0aef21f4f17173b8b): perf score=10.125253
I20260812 06:18:54.710808   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: FlushMRSOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.127s	user 0.104s	sys 0.019s Metrics: {"bytes_written":8615323,"cfile_init":1,"compiler_manager_pool.queue_time_us":251,"delete_count":0,"dirs.queue_time_us":77,"dirs.run_cpu_time_us":230,"dirs.run_wall_time_us":896,"drs_written":1,"lbm_read_time_us":112,"lbm_reads_lt_1ms":4,"lbm_write_time_us":26779,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":466,"peak_mem_usage":0,"reinsert_count":0,"rows_written":102,"thread_start_us":100,"threads_started":1,"update_count":1050}
I20260812 06:18:54.711966   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling LogGCOp(1a99d49b34a941f0aef21f4f17173b8b): free 11976772 bytes of WAL
I20260812 06:18:54.712288   872 log_reader.cc:385] T 1a99d49b34a941f0aef21f4f17173b8b: removed 1 log segments from log reader
I20260812 06:18:54.712366   872 log.cc:1079] T 1a99d49b34a941f0aef21f4f17173b8b P 1afc727aadf348d6ac7aaba592f9cbda: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534140020-757-0/minicluster-data/ts-0-root/wals/1a99d49b34a941f0aef21f4f17173b8b/wal-000000001 (ops 1-6)
I20260812 06:18:54.714782   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: LogGCOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:18:54.715189   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b): perf score=2.188937
I20260812 06:18:54.729588   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.014s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5124,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:54.730155   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling MajorDeltaCompactionOp(1a99d49b34a941f0aef21f4f17173b8b): perf score=1.000000
I20260812 06:18:54.860111   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: MajorDeltaCompactionOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.130s	user 0.109s	sys 0.016s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16487926,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1006,"lbm_read_time_us":6217,"lbm_reads_lt_1ms":364,"lbm_write_time_us":22311,"lbm_writes_lt_1ms":343,"mutex_wait_us":54,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":10880,"thread_start_us":382,"threads_started":5,"update_count":1500}
I20260812 06:18:54.862028   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling UndoDeltaBlockGCOp(1a99d49b34a941f0aef21f4f17173b8b): 8206537 bytes on disk
I20260812 06:18:54.863166   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: UndoDeltaBlockGCOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":106,"lbm_reads_lt_1ms":4}
I20260812 06:18:54.863900   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b): perf score=8.142062
I20260812 06:18:54.904199   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.040s	user 0.018s	sys 0.019s Metrics: {"bytes_written":10256284,"delete_count":0,"lbm_write_time_us":18421,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":252,"reinsert_count":0,"update_count":1250}
I20260812 06:18:54.904860   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b): perf score=1.000000
I20260812 06:18:54.917510   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.012s	user 0.008s	sys 0.001s Metrics: {"bytes_written":2051402,"delete_count":0,"lbm_write_time_us":3302,"lbm_writes_lt_1ms":53,"reinsert_count":0,"update_count":250}
I20260812 06:18:54.918110   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling MajorDeltaCompactionOp(1a99d49b34a941f0aef21f4f17173b8b): perf score=1.000000
I20260812 06:18:55.049600   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: MajorDeltaCompactionOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.131s	user 0.105s	sys 0.025s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16487885,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":190,"lbm_read_time_us":7438,"lbm_reads_lt_1ms":364,"lbm_write_time_us":24682,"lbm_writes_lt_1ms":343,"mutex_wait_us":42,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":8320,"update_count":1500}
I20260812 06:18:55.050308   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b): perf score=10.126437
I20260812 06:18:55.104132   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.054s	user 0.024s	sys 0.012s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":15764,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:55.104707   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b): perf score=2.188937
I20260812 06:18:55.117723   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4503,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:55.118259   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling MajorDeltaCompactionOp(1a99d49b34a941f0aef21f4f17173b8b): perf score=1.000000
I20260812 06:18:55.249760   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: MajorDeltaCompactionOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.131s	user 0.111s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590350,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":668,"lbm_read_time_us":8733,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25166,"lbm_writes_lt_1ms":443,"mutex_wait_us":1,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:55.250252   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b): perf score=10.126437
I20260812 06:18:55.293334   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.043s	user 0.026s	sys 0.016s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":19382,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:55.293931   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling MajorDeltaCompactionOp(1a99d49b34a941f0aef21f4f17173b8b): perf score=1.000000
I20260812 06:18:55.404377   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: MajorDeltaCompactionOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.110s	user 0.070s	sys 0.040s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16487815,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":134,"lbm_read_time_us":6295,"lbm_reads_lt_1ms":363,"lbm_write_time_us":21619,"lbm_writes_lt_1ms":343,"mutex_wait_us":46,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":1500}
I20260812 06:18:55.404937   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b): perf score=10.126437
I20260812 06:18:55.451617   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.046s	user 0.033s	sys 0.003s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17561,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:55.452189   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b): perf score=2.188937
I20260812 06:18:55.464237   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4567,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:55.464905   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling MajorDeltaCompactionOp(1a99d49b34a941f0aef21f4f17173b8b): perf score=1.000000
I20260812 06:18:55.611016   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: MajorDeltaCompactionOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.146s	user 0.120s	sys 0.019s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590347,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":786,"lbm_read_time_us":8212,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26892,"lbm_writes_lt_1ms":443,"mutex_wait_us":30,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3968,"update_count":2000}
I20260812 06:18:55.611567   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b): perf score=10.126437
I20260812 06:18:55.658084   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.046s	user 0.018s	sys 0.020s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16188,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:55.658624   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b): perf score=2.188937
I20260812 06:18:55.671285   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4141,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:55.672259   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling MajorDeltaCompactionOp(1a99d49b34a941f0aef21f4f17173b8b): perf score=1.000000
I20260812 06:18:55.792335   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: MajorDeltaCompactionOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.120s	user 0.108s	sys 0.012s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590348,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":245,"lbm_read_time_us":7187,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24497,"lbm_writes_lt_1ms":443,"mutex_wait_us":65,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12928,"update_count":2000}
I20260812 06:18:55.793115   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b): perf score=10.126437
I20260812 06:18:55.837755   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.044s	user 0.024s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17615,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:55.838366   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b): perf score=2.188937
I20260812 06:18:55.857645   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.019s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6741,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:55.858443   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling MajorDeltaCompactionOp(1a99d49b34a941f0aef21f4f17173b8b): perf score=1.000000
I20260812 06:18:55.993006   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: MajorDeltaCompactionOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.134s	user 0.114s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590346,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1072,"lbm_read_time_us":7503,"lbm_reads_lt_1ms":464,"lbm_write_time_us":28828,"lbm_writes_lt_1ms":443,"mutex_wait_us":60,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:18:55.993866   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b): perf score=10.126437
I20260812 06:18:56.044023   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.050s	user 0.015s	sys 0.031s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16367,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:56.044982   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b): perf score=2.188937
I20260812 06:18:56.058935   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5415,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:56.059589   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling FlushMRSOp(1a99d49b34a941f0aef21f4f17173b8b): perf score=1.000000
I20260812 06:18:56.087575   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: FlushMRSOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.028s	user 0.026s	sys 0.000s Metrics: {"bytes_written":1234474,"cfile_init":1,"dirs.queue_time_us":91,"dirs.run_cpu_time_us":508,"dirs.run_wall_time_us":1868,"drs_written":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2054,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:56.088475   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling LogGCOp(1a99d49b34a941f0aef21f4f17173b8b): free 120553378 bytes of WAL
I20260812 06:18:56.088842   872 log_reader.cc:385] T 1a99d49b34a941f0aef21f4f17173b8b: removed 12 log segments from log reader
I20260812 06:18:56.088907   872 log.cc:1079] T 1a99d49b34a941f0aef21f4f17173b8b P 1afc727aadf348d6ac7aaba592f9cbda: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534140020-757-0/minicluster-data/ts-0-root/wals/1a99d49b34a941f0aef21f4f17173b8b/wal-000000002 (ops 7-11)
I20260812 06:18:56.088948   872 log.cc:1079] T 1a99d49b34a941f0aef21f4f17173b8b P 1afc727aadf348d6ac7aaba592f9cbda: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534140020-757-0/minicluster-data/ts-0-root/wals/1a99d49b34a941f0aef21f4f17173b8b/wal-000000003 (ops 12-16)
I20260812 06:18:56.088972   872 log.cc:1079] T 1a99d49b34a941f0aef21f4f17173b8b P 1afc727aadf348d6ac7aaba592f9cbda: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534140020-757-0/minicluster-data/ts-0-root/wals/1a99d49b34a941f0aef21f4f17173b8b/wal-000000004 (ops 17-21)
I20260812 06:18:56.089005   872 log.cc:1079] T 1a99d49b34a941f0aef21f4f17173b8b P 1afc727aadf348d6ac7aaba592f9cbda: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534140020-757-0/minicluster-data/ts-0-root/wals/1a99d49b34a941f0aef21f4f17173b8b/wal-000000005 (ops 22-26)
I20260812 06:18:56.089035   872 log.cc:1079] T 1a99d49b34a941f0aef21f4f17173b8b P 1afc727aadf348d6ac7aaba592f9cbda: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534140020-757-0/minicluster-data/ts-0-root/wals/1a99d49b34a941f0aef21f4f17173b8b/wal-000000006 (ops 27-31)
I20260812 06:18:56.089058   872 log.cc:1079] T 1a99d49b34a941f0aef21f4f17173b8b P 1afc727aadf348d6ac7aaba592f9cbda: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534140020-757-0/minicluster-data/ts-0-root/wals/1a99d49b34a941f0aef21f4f17173b8b/wal-000000007 (ops 32-36)
I20260812 06:18:56.089082   872 log.cc:1079] T 1a99d49b34a941f0aef21f4f17173b8b P 1afc727aadf348d6ac7aaba592f9cbda: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534140020-757-0/minicluster-data/ts-0-root/wals/1a99d49b34a941f0aef21f4f17173b8b/wal-000000008 (ops 37-40)
I20260812 06:18:56.089104   872 log.cc:1079] T 1a99d49b34a941f0aef21f4f17173b8b P 1afc727aadf348d6ac7aaba592f9cbda: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534140020-757-0/minicluster-data/ts-0-root/wals/1a99d49b34a941f0aef21f4f17173b8b/wal-000000009 (ops 41-45)
I20260812 06:18:56.089126   872 log.cc:1079] T 1a99d49b34a941f0aef21f4f17173b8b P 1afc727aadf348d6ac7aaba592f9cbda: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534140020-757-0/minicluster-data/ts-0-root/wals/1a99d49b34a941f0aef21f4f17173b8b/wal-000000010 (ops 46-50)
I20260812 06:18:56.089149   872 log.cc:1079] T 1a99d49b34a941f0aef21f4f17173b8b P 1afc727aadf348d6ac7aaba592f9cbda: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534140020-757-0/minicluster-data/ts-0-root/wals/1a99d49b34a941f0aef21f4f17173b8b/wal-000000011 (ops 51-55)
I20260812 06:18:56.089177   872 log.cc:1079] T 1a99d49b34a941f0aef21f4f17173b8b P 1afc727aadf348d6ac7aaba592f9cbda: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534140020-757-0/minicluster-data/ts-0-root/wals/1a99d49b34a941f0aef21f4f17173b8b/wal-000000012 (ops 56-60)
I20260812 06:18:56.089202   872 log.cc:1079] T 1a99d49b34a941f0aef21f4f17173b8b P 1afc727aadf348d6ac7aaba592f9cbda: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534140020-757-0/minicluster-data/ts-0-root/wals/1a99d49b34a941f0aef21f4f17173b8b/wal-000000013 (ops 61-64)
I20260812 06:18:56.118377   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: LogGCOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.030s	user 0.000s	sys 0.028s Metrics: {}
I20260812 06:18:56.118891   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b): perf score=2.188937
I20260812 06:18:56.149888   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.031s	user 0.003s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4822,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:56.150434   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b): perf score=2.188937
I20260812 06:18:56.161725   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.011s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4058,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:56.162288   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling MajorDeltaCompactionOp(1a99d49b34a941f0aef21f4f17173b8b): perf score=1.000000
I20260812 06:18:56.366782   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: MajorDeltaCompactionOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.204s	user 0.145s	sys 0.060s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28795410,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1108,"lbm_read_time_us":13765,"lbm_reads_lt_1ms":674,"lbm_write_time_us":34149,"lbm_writes_lt_1ms":643,"mutex_wait_us":74,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3584,"thread_start_us":84,"threads_started":1,"update_count":3000}
I20260812 06:18:56.368680   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b): perf score=14.095187
I20260812 06:18:56.420249   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.051s	user 0.032s	sys 0.012s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21375,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:56.420804   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling UndoDeltaBlockGCOp(1a99d49b34a941f0aef21f4f17173b8b): 472 bytes on disk
I20260812 06:18:56.421717   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: UndoDeltaBlockGCOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":227,"lbm_reads_lt_1ms":4}
I20260812 06:18:56.422243   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling MajorDeltaCompactionOp(1a99d49b34a941f0aef21f4f17173b8b): perf score=1.000000
I20260812 06:18:56.569065   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: MajorDeltaCompactionOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.147s	user 0.122s	sys 0.024s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20590228,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":381,"lbm_read_time_us":9209,"lbm_reads_lt_1ms":463,"lbm_write_time_us":25862,"lbm_writes_lt_1ms":443,"mutex_wait_us":2,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:56.569839   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b): perf score=11.118625
I20260812 06:18:56.607724   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.037s	user 0.027s	sys 0.008s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":15542,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:56.608369   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b): perf score=2.188937
I20260812 06:18:56.621219   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.013s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4820,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:56.621680   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling MajorDeltaCompactionOp(1a99d49b34a941f0aef21f4f17173b8b): perf score=1.000000
I20260812 06:18:56.758963   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: MajorDeltaCompactionOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.137s	user 0.086s	sys 0.051s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590340,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":923,"lbm_read_time_us":8304,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27720,"lbm_writes_lt_1ms":443,"mutex_wait_us":77,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":19072,"update_count":2000}
I20260812 06:18:56.760399   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b): perf score=10.126437
I20260812 06:18:56.798786   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.038s	user 0.018s	sys 0.017s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16522,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:56.799345   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b): perf score=2.188937
I20260812 06:18:56.810352   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4179,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:56.810921   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling MajorDeltaCompactionOp(1a99d49b34a941f0aef21f4f17173b8b): perf score=1.000000
I20260812 06:18:56.938405   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: MajorDeltaCompactionOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.127s	user 0.098s	sys 0.026s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590347,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":558,"lbm_read_time_us":10070,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22297,"lbm_writes_lt_1ms":443,"mutex_wait_us":253,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":2000}
I20260812 06:18:56.939035   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b): perf score=10.126437
I20260812 06:18:56.978191   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.039s	user 0.018s	sys 0.017s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15722,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:56.978801   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling MajorDeltaCompactionOp(1a99d49b34a941f0aef21f4f17173b8b): perf score=1.000000
I20260812 06:18:57.082067   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: MajorDeltaCompactionOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.103s	user 0.086s	sys 0.016s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16487817,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":240,"lbm_read_time_us":5674,"lbm_reads_lt_1ms":363,"lbm_write_time_us":20563,"lbm_writes_lt_1ms":343,"mutex_wait_us":48,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":43520,"update_count":1500}
I20260812 06:18:57.082832   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b): perf score=10.126437
I20260812 06:18:57.119508   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.036s	user 0.025s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15417,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:57.120182   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling MajorDeltaCompactionOp(1a99d49b34a941f0aef21f4f17173b8b): perf score=1.000000
I20260812 06:18:57.228133   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: MajorDeltaCompactionOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.108s	user 0.091s	sys 0.016s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16487816,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":662,"lbm_read_time_us":7115,"lbm_reads_lt_1ms":363,"lbm_write_time_us":19504,"lbm_writes_lt_1ms":343,"mutex_wait_us":292,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":53120,"update_count":1500}
I20260812 06:18:57.228839   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b): perf score=10.126437
I20260812 06:18:57.265202   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.036s	user 0.015s	sys 0.020s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16175,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:57.265781   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling MajorDeltaCompactionOp(1a99d49b34a941f0aef21f4f17173b8b): perf score=1.000000
I20260812 06:18:57.375855   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: MajorDeltaCompactionOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.110s	user 0.097s	sys 0.012s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16487817,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1068,"lbm_read_time_us":6804,"lbm_reads_lt_1ms":363,"lbm_write_time_us":20692,"lbm_writes_lt_1ms":343,"mutex_wait_us":329,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":4352,"update_count":1500}
I20260812 06:18:57.376581   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b): perf score=10.126437
I20260812 06:18:57.423326   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.046s	user 0.018s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18778,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:57.423928   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b): perf score=2.188937
I20260812 06:18:57.437747   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4512,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:57.438318   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling MajorDeltaCompactionOp(1a99d49b34a941f0aef21f4f17173b8b): perf score=1.000000
I20260812 06:18:57.572356   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: MajorDeltaCompactionOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.134s	user 0.114s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590347,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":259,"lbm_read_time_us":11066,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25712,"lbm_writes_lt_1ms":443,"mutex_wait_us":2,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5376,"update_count":2000}
I20260812 06:18:57.573202   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b): perf score=10.126437
I20260812 06:18:57.613415   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.040s	user 0.027s	sys 0.012s Metrics: {"bytes_written":12307494,"delete_count":0,"lbm_write_time_us":17287,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":1500}
I20260812 06:18:57.613950   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b): perf score=2.188937
I20260812 06:18:57.626309   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4709,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:57.627002   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling FlushMRSOp(1a99d49b34a941f0aef21f4f17173b8b): perf score=1.000000
I20260812 06:18:57.661224   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: FlushMRSOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.034s	user 0.030s	sys 0.004s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":66,"dirs.run_cpu_time_us":191,"dirs.run_wall_time_us":1770,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1560,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30,"spinlock_wait_cycles":1792}
I20260812 06:18:57.661971   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling LogGCOp(1a99d49b34a941f0aef21f4f17173b8b): free 121006383 bytes of WAL
I20260812 06:18:57.662201   872 log_reader.cc:385] T 1a99d49b34a941f0aef21f4f17173b8b: removed 12 log segments from log reader
I20260812 06:18:57.662245   872 log.cc:1079] T 1a99d49b34a941f0aef21f4f17173b8b P 1afc727aadf348d6ac7aaba592f9cbda: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534140020-757-0/minicluster-data/ts-0-root/wals/1a99d49b34a941f0aef21f4f17173b8b/wal-000000014 (ops 65-69)
I20260812 06:18:57.662273   872 log.cc:1079] T 1a99d49b34a941f0aef21f4f17173b8b P 1afc727aadf348d6ac7aaba592f9cbda: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534140020-757-0/minicluster-data/ts-0-root/wals/1a99d49b34a941f0aef21f4f17173b8b/wal-000000015 (ops 70-74)
I20260812 06:18:57.662338   872 log.cc:1079] T 1a99d49b34a941f0aef21f4f17173b8b P 1afc727aadf348d6ac7aaba592f9cbda: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534140020-757-0/minicluster-data/ts-0-root/wals/1a99d49b34a941f0aef21f4f17173b8b/wal-000000016 (ops 75-79)
I20260812 06:18:57.662374   872 log.cc:1079] T 1a99d49b34a941f0aef21f4f17173b8b P 1afc727aadf348d6ac7aaba592f9cbda: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534140020-757-0/minicluster-data/ts-0-root/wals/1a99d49b34a941f0aef21f4f17173b8b/wal-000000017 (ops 80-84)
I20260812 06:18:57.662392   872 log.cc:1079] T 1a99d49b34a941f0aef21f4f17173b8b P 1afc727aadf348d6ac7aaba592f9cbda: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534140020-757-0/minicluster-data/ts-0-root/wals/1a99d49b34a941f0aef21f4f17173b8b/wal-000000018 (ops 85-89)
I20260812 06:18:57.662447   872 log.cc:1079] T 1a99d49b34a941f0aef21f4f17173b8b P 1afc727aadf348d6ac7aaba592f9cbda: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534140020-757-0/minicluster-data/ts-0-root/wals/1a99d49b34a941f0aef21f4f17173b8b/wal-000000019 (ops 90-94)
I20260812 06:18:57.662485   872 log.cc:1079] T 1a99d49b34a941f0aef21f4f17173b8b P 1afc727aadf348d6ac7aaba592f9cbda: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534140020-757-0/minicluster-data/ts-0-root/wals/1a99d49b34a941f0aef21f4f17173b8b/wal-000000020 (ops 95-99)
I20260812 06:18:57.662532   872 log.cc:1079] T 1a99d49b34a941f0aef21f4f17173b8b P 1afc727aadf348d6ac7aaba592f9cbda: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534140020-757-0/minicluster-data/ts-0-root/wals/1a99d49b34a941f0aef21f4f17173b8b/wal-000000021 (ops 100-104)
I20260812 06:18:57.662575   872 log.cc:1079] T 1a99d49b34a941f0aef21f4f17173b8b P 1afc727aadf348d6ac7aaba592f9cbda: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534140020-757-0/minicluster-data/ts-0-root/wals/1a99d49b34a941f0aef21f4f17173b8b/wal-000000022 (ops 105-109)
I20260812 06:18:57.662616   872 log.cc:1079] T 1a99d49b34a941f0aef21f4f17173b8b P 1afc727aadf348d6ac7aaba592f9cbda: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534140020-757-0/minicluster-data/ts-0-root/wals/1a99d49b34a941f0aef21f4f17173b8b/wal-000000023 (ops 110-114)
I20260812 06:18:57.662657   872 log.cc:1079] T 1a99d49b34a941f0aef21f4f17173b8b P 1afc727aadf348d6ac7aaba592f9cbda: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534140020-757-0/minicluster-data/ts-0-root/wals/1a99d49b34a941f0aef21f4f17173b8b/wal-000000024 (ops 115-118)
I20260812 06:18:57.662698   872 log.cc:1079] T 1a99d49b34a941f0aef21f4f17173b8b P 1afc727aadf348d6ac7aaba592f9cbda: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534140020-757-0/minicluster-data/ts-0-root/wals/1a99d49b34a941f0aef21f4f17173b8b/wal-000000025 (ops 119-123)
I20260812 06:18:57.689373   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: LogGCOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.027s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:18:57.689977   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b): perf score=3.181125
I20260812 06:18:57.704677   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.014s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":5475,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:57.705330   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling LogGCOp(1a99d49b34a941f0aef21f4f17173b8b): free 12017983 bytes of WAL
I20260812 06:18:57.705585   872 log_reader.cc:385] T 1a99d49b34a941f0aef21f4f17173b8b: removed 1 log segments from log reader
I20260812 06:18:57.705649   872 log.cc:1079] T 1a99d49b34a941f0aef21f4f17173b8b P 1afc727aadf348d6ac7aaba592f9cbda: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534140020-757-0/minicluster-data/ts-0-root/wals/1a99d49b34a941f0aef21f4f17173b8b/wal-000000026 (ops 124-128)
I20260812 06:18:57.707931   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: LogGCOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:18:57.708242   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b): perf score=2.188937
I20260812 06:18:57.720359   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4068,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:57.721035   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling MajorDeltaCompactionOp(1a99d49b34a941f0aef21f4f17173b8b): perf score=1.000000
I20260812 06:18:57.896672   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: MajorDeltaCompactionOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.175s	user 0.125s	sys 0.045s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28795400,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1600,"lbm_read_time_us":10333,"lbm_reads_lt_1ms":666,"lbm_write_time_us":36004,"lbm_writes_lt_1ms":643,"mutex_wait_us":577,"peak_mem_usage":75542472,"reinsert_count":0,"thread_start_us":110,"threads_started":1,"update_count":3000}
I20260812 06:18:57.897349   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling UndoDeltaBlockGCOp(1a99d49b34a941f0aef21f4f17173b8b): 475 bytes on disk
I20260812 06:18:57.897847   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: UndoDeltaBlockGCOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":77,"lbm_reads_lt_1ms":4}
I20260812 06:18:57.898631   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b): perf score=14.095187
I20260812 06:18:57.953905   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.055s	user 0.036s	sys 0.018s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24885,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:57.954372   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b): perf score=2.188937
I20260812 06:18:57.967556   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4855,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:57.968063   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling MajorDeltaCompactionOp(1a99d49b34a941f0aef21f4f17173b8b): perf score=1.000000
I20260812 06:18:58.129277   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: MajorDeltaCompactionOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.161s	user 0.141s	sys 0.016s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24692759,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":657,"lbm_read_time_us":10942,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32825,"lbm_writes_lt_1ms":543,"mutex_wait_us":43,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12928,"update_count":2500}
I20260812 06:18:58.129936   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b): perf score=11.118625
I20260812 06:18:58.164374   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.034s	user 0.018s	sys 0.012s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":14732,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:58.164983   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b): perf score=2.188937
I20260812 06:18:58.182124   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.017s	user 0.010s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5860,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:58.182699   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling MajorDeltaCompactionOp(1a99d49b34a941f0aef21f4f17173b8b): perf score=1.000000
I20260812 06:18:58.324141   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: MajorDeltaCompactionOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.141s	user 0.113s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590337,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":574,"lbm_read_time_us":9222,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26156,"lbm_writes_lt_1ms":443,"mutex_wait_us":83,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14976,"update_count":2000}
I20260812 06:18:58.324708   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b): perf score=10.126437
I20260812 06:18:58.359602   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.035s	user 0.018s	sys 0.013s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15239,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:58.360200   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b): perf score=2.188937
I20260812 06:18:58.371620   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4330,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:58.372095   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling MajorDeltaCompactionOp(1a99d49b34a941f0aef21f4f17173b8b): perf score=1.000000
I20260812 06:18:58.522006   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: MajorDeltaCompactionOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.150s	user 0.117s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590348,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":882,"lbm_read_time_us":10383,"lbm_reads_lt_1ms":472,"lbm_write_time_us":32358,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":99,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:18:58.522768   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b): perf score=10.126437
I20260812 06:18:58.580833   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.058s	user 0.031s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18907,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:58.581686   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b): perf score=2.188937
I20260812 06:18:58.596660   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.015s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5819,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:58.597164   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling MajorDeltaCompactionOp(1a99d49b34a941f0aef21f4f17173b8b): perf score=1.000000
I20260812 06:18:58.772919   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: MajorDeltaCompactionOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.176s	user 0.119s	sys 0.056s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590347,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1195,"lbm_read_time_us":11292,"lbm_reads_lt_1ms":472,"lbm_write_time_us":30452,"lbm_writes_lt_1ms":443,"mutex_wait_us":365,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:18:58.773679   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b): perf score=10.126437
I20260812 06:18:58.821995   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.048s	user 0.027s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17746,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":1500}
I20260812 06:18:58.822574   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b): perf score=2.188937
I20260812 06:18:58.834700   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.012s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4522,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:58.835587   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling MajorDeltaCompactionOp(1a99d49b34a941f0aef21f4f17173b8b): perf score=1.000000
I20260812 06:18:58.967242   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: MajorDeltaCompactionOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.131s	user 0.110s	sys 0.021s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590347,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":282,"lbm_read_time_us":9192,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26410,"lbm_writes_lt_1ms":443,"mutex_wait_us":55,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":24448,"update_count":2000}
I20260812 06:18:58.968191   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b): perf score=10.126437
I20260812 06:18:59.016862   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.048s	user 0.026s	sys 0.016s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":19395,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:59.017396   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b): perf score=2.188937
I20260812 06:18:59.029253   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4160,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:59.029748   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling MajorDeltaCompactionOp(1a99d49b34a941f0aef21f4f17173b8b): perf score=1.000000
I20260812 06:18:59.164397   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: MajorDeltaCompactionOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.134s	user 0.118s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590345,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":219,"lbm_read_time_us":9639,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26229,"lbm_writes_lt_1ms":443,"mutex_wait_us":38,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3712,"update_count":2000}
I20260812 06:18:59.165009   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b): perf score=10.126437
I20260812 06:18:59.215162   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.050s	user 0.035s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18529,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:59.215970   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling FlushMRSOp(1a99d49b34a941f0aef21f4f17173b8b): perf score=1.000000
I20260812 06:18:59.255322   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: FlushMRSOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.039s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":88,"dirs.run_cpu_time_us":229,"dirs.run_wall_time_us":1819,"drs_written":1,"lbm_read_time_us":88,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2297,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:59.256163   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling LogGCOp(1a99d49b34a941f0aef21f4f17173b8b): free 121006640 bytes of WAL
I20260812 06:18:59.256400   872 log_reader.cc:385] T 1a99d49b34a941f0aef21f4f17173b8b: removed 12 log segments from log reader
I20260812 06:18:59.256470   872 log.cc:1079] T 1a99d49b34a941f0aef21f4f17173b8b P 1afc727aadf348d6ac7aaba592f9cbda: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534140020-757-0/minicluster-data/ts-0-root/wals/1a99d49b34a941f0aef21f4f17173b8b/wal-000000027 (ops 129-133)
I20260812 06:18:59.256525   872 log.cc:1079] T 1a99d49b34a941f0aef21f4f17173b8b P 1afc727aadf348d6ac7aaba592f9cbda: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534140020-757-0/minicluster-data/ts-0-root/wals/1a99d49b34a941f0aef21f4f17173b8b/wal-000000028 (ops 134-138)
I20260812 06:18:59.256618   872 log.cc:1079] T 1a99d49b34a941f0aef21f4f17173b8b P 1afc727aadf348d6ac7aaba592f9cbda: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534140020-757-0/minicluster-data/ts-0-root/wals/1a99d49b34a941f0aef21f4f17173b8b/wal-000000029 (ops 139-143)
I20260812 06:18:59.256678   872 log.cc:1079] T 1a99d49b34a941f0aef21f4f17173b8b P 1afc727aadf348d6ac7aaba592f9cbda: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534140020-757-0/minicluster-data/ts-0-root/wals/1a99d49b34a941f0aef21f4f17173b8b/wal-000000030 (ops 144-148)
I20260812 06:18:59.256723   872 log.cc:1079] T 1a99d49b34a941f0aef21f4f17173b8b P 1afc727aadf348d6ac7aaba592f9cbda: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534140020-757-0/minicluster-data/ts-0-root/wals/1a99d49b34a941f0aef21f4f17173b8b/wal-000000031 (ops 149-152)
I20260812 06:18:59.256762   872 log.cc:1079] T 1a99d49b34a941f0aef21f4f17173b8b P 1afc727aadf348d6ac7aaba592f9cbda: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534140020-757-0/minicluster-data/ts-0-root/wals/1a99d49b34a941f0aef21f4f17173b8b/wal-000000032 (ops 153-157)
I20260812 06:18:59.256801   872 log.cc:1079] T 1a99d49b34a941f0aef21f4f17173b8b P 1afc727aadf348d6ac7aaba592f9cbda: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534140020-757-0/minicluster-data/ts-0-root/wals/1a99d49b34a941f0aef21f4f17173b8b/wal-000000033 (ops 158-162)
I20260812 06:18:59.256840   872 log.cc:1079] T 1a99d49b34a941f0aef21f4f17173b8b P 1afc727aadf348d6ac7aaba592f9cbda: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534140020-757-0/minicluster-data/ts-0-root/wals/1a99d49b34a941f0aef21f4f17173b8b/wal-000000034 (ops 163-167)
I20260812 06:18:59.256879   872 log.cc:1079] T 1a99d49b34a941f0aef21f4f17173b8b P 1afc727aadf348d6ac7aaba592f9cbda: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534140020-757-0/minicluster-data/ts-0-root/wals/1a99d49b34a941f0aef21f4f17173b8b/wal-000000035 (ops 168-172)
I20260812 06:18:59.256917   872 log.cc:1079] T 1a99d49b34a941f0aef21f4f17173b8b P 1afc727aadf348d6ac7aaba592f9cbda: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534140020-757-0/minicluster-data/ts-0-root/wals/1a99d49b34a941f0aef21f4f17173b8b/wal-000000036 (ops 173-177)
I20260812 06:18:59.256954   872 log.cc:1079] T 1a99d49b34a941f0aef21f4f17173b8b P 1afc727aadf348d6ac7aaba592f9cbda: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534140020-757-0/minicluster-data/ts-0-root/wals/1a99d49b34a941f0aef21f4f17173b8b/wal-000000037 (ops 178-182)
I20260812 06:18:59.257011   872 log.cc:1079] T 1a99d49b34a941f0aef21f4f17173b8b P 1afc727aadf348d6ac7aaba592f9cbda: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534140020-757-0/minicluster-data/ts-0-root/wals/1a99d49b34a941f0aef21f4f17173b8b/wal-000000038 (ops 183-187)
I20260812 06:18:59.284253   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: LogGCOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.028s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:18:59.285094   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling UndoDeltaBlockGCOp(1a99d49b34a941f0aef21f4f17173b8b): 482 bytes on disk
I20260812 06:18:59.285727   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: UndoDeltaBlockGCOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":72,"lbm_reads_lt_1ms":4}
I20260812 06:18:59.286448   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b): perf score=6.157687
I20260812 06:18:59.317775   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.031s	user 0.017s	sys 0.008s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":11186,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:18:59.319015   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling MajorDeltaCompactionOp(1a99d49b34a941f0aef21f4f17173b8b): perf score=1.000000
I20260812 06:18:59.500896   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: MajorDeltaCompactionOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.182s	user 0.125s	sys 0.055s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24692760,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":623,"lbm_read_time_us":10642,"lbm_reads_lt_1ms":564,"lbm_write_time_us":33367,"lbm_writes_lt_1ms":543,"mutex_wait_us":25,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12928,"thread_start_us":118,"threads_started":1,"update_count":2500}
I20260812 06:18:59.501592   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b): perf score=14.095187
I20260812 06:18:59.560792   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.059s	user 0.029s	sys 0.029s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21541,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:59.561580   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b): perf score=2.188937
I20260812 06:18:59.578707   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: FlushDeltaMemStoresOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.017s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6657,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:59.579195   944 maintenance_manager.cc:419] P 1afc727aadf348d6ac7aaba592f9cbda: Scheduling MajorDeltaCompactionOp(1a99d49b34a941f0aef21f4f17173b8b): perf score=1.000000
I20260812 06:18:59.633716   757 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.148s	user 1.888s	sys 0.143s
I20260812 06:18:59.711941   757 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.078s	user 0.001s	sys 0.000s
I20260812 06:18:59.712690   757 tablet_server.cc:179] TabletServer@127.0.189.65:0 shutting down...
I20260812 06:18:59.739822   872 maintenance_manager.cc:643] P 1afc727aadf348d6ac7aaba592f9cbda: MajorDeltaCompactionOp(1a99d49b34a941f0aef21f4f17173b8b) complete. Timing: real 0.160s	user 0.119s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24692757,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":516,"lbm_read_time_us":14186,"lbm_reads_lt_1ms":568,"lbm_write_time_us":24754,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":28160,"update_count":2500}
I20260812 06:18:59.740790   757 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:59.741290   757 tablet_replica.cc:333] T 1a99d49b34a941f0aef21f4f17173b8b P 1afc727aadf348d6ac7aaba592f9cbda: stopping tablet replica
I20260812 06:18:59.741578   757 raft_consensus.cc:2243] T 1a99d49b34a941f0aef21f4f17173b8b P 1afc727aadf348d6ac7aaba592f9cbda [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:59.741854   757 raft_consensus.cc:2272] T 1a99d49b34a941f0aef21f4f17173b8b P 1afc727aadf348d6ac7aaba592f9cbda [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:59.749258   757 tablet_server.cc:196] TabletServer@127.0.189.65:0 shutdown complete.
I20260812 06:18:59.787194   757 master.cc:562] Master@127.0.189.126:41719 shutting down...
I20260812 06:18:59.791345   757 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 2589840e739147ee95725a534cfe8ea3 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:59.791536   757 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 2589840e739147ee95725a534cfe8ea3 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:59.791596   757 tablet_replica.cc:333] T 00000000000000000000000000000000 P 2589840e739147ee95725a534cfe8ea3: stopping tablet replica
I20260812 06:18:59.804498   757 master.cc:584] Master@127.0.189.126:41719 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5741 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:59.907433   757 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.0.189.126:39507
I20260812 06:18:59.907820   757 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:59.910252   978 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:59.910303   977 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:59.910485   980 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:59.910650   757 server_base.cc:1061] running on GCE node
I20260812 06:18:59.910885   757 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:59.910946   757 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:59.910965   757 hybrid_clock.cc:648] HybridClock initialized: now 1786515539910965 us; error 0 us; skew 500 ppm
I20260812 06:18:59.911909   757 webserver.cc:533] Webserver started at http://127.0.189.126:40277/ using document root <none> and password file <none>
I20260812 06:18:59.912070   757 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:59.912127   757 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:59.912196   757 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:59.912755   757 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534140020-757-0/minicluster-data/master-0-root/instance:
uuid: "0facc64c120c4ab3b9f59e9fbad399af"
format_stamp: "Formatted at 2026-08-12 06:18:59 on dist-test-slave-rgb1"
I20260812 06:18:59.914603   757 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:59.915818   987 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:59.916260   757 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:59.916453   757 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534140020-757-0/minicluster-data/master-0-root
uuid: "0facc64c120c4ab3b9f59e9fbad399af"
format_stamp: "Formatted at 2026-08-12 06:18:59 on dist-test-slave-rgb1"
I20260812 06:18:59.916564   757 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534140020-757-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534140020-757-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534140020-757-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:59.928211   757 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:59.928753   757 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:59.933979   757 rpc_server.cc:307] RPC server started. Bound to: 127.0.189.126:39507
I20260812 06:18:59.936242  1045 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.0.189.126:39507 every 8 connection(s)
I20260812 06:18:59.936753  1046 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:59.939728  1046 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 0facc64c120c4ab3b9f59e9fbad399af: Bootstrap starting.
I20260812 06:18:59.940753  1046 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 0facc64c120c4ab3b9f59e9fbad399af: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:59.941982  1046 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 0facc64c120c4ab3b9f59e9fbad399af: No bootstrap required, opened a new log
I20260812 06:18:59.942462  1046 raft_consensus.cc:359] T 00000000000000000000000000000000 P 0facc64c120c4ab3b9f59e9fbad399af [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0facc64c120c4ab3b9f59e9fbad399af" member_type: VOTER }
I20260812 06:18:59.942561  1046 raft_consensus.cc:385] T 00000000000000000000000000000000 P 0facc64c120c4ab3b9f59e9fbad399af [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:59.942586  1046 raft_consensus.cc:740] T 00000000000000000000000000000000 P 0facc64c120c4ab3b9f59e9fbad399af [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 0facc64c120c4ab3b9f59e9fbad399af, State: Initialized, Role: FOLLOWER
I20260812 06:18:59.942780  1046 consensus_queue.cc:260] T 00000000000000000000000000000000 P 0facc64c120c4ab3b9f59e9fbad399af [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: "0facc64c120c4ab3b9f59e9fbad399af" member_type: VOTER }
I20260812 06:18:59.942881  1046 raft_consensus.cc:399] T 00000000000000000000000000000000 P 0facc64c120c4ab3b9f59e9fbad399af [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:59.942909  1046 raft_consensus.cc:493] T 00000000000000000000000000000000 P 0facc64c120c4ab3b9f59e9fbad399af [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:59.942939  1046 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 0facc64c120c4ab3b9f59e9fbad399af [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:59.943747  1046 raft_consensus.cc:515] T 00000000000000000000000000000000 P 0facc64c120c4ab3b9f59e9fbad399af [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0facc64c120c4ab3b9f59e9fbad399af" member_type: VOTER }
I20260812 06:18:59.943871  1046 leader_election.cc:304] T 00000000000000000000000000000000 P 0facc64c120c4ab3b9f59e9fbad399af [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: 0facc64c120c4ab3b9f59e9fbad399af; no voters: 
I20260812 06:18:59.944088  1046 leader_election.cc:290] T 00000000000000000000000000000000 P 0facc64c120c4ab3b9f59e9fbad399af [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:59.944347  1049 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 0facc64c120c4ab3b9f59e9fbad399af [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:59.944638  1049 raft_consensus.cc:697] T 00000000000000000000000000000000 P 0facc64c120c4ab3b9f59e9fbad399af [term 1 LEADER]: Becoming Leader. State: Replica: 0facc64c120c4ab3b9f59e9fbad399af, State: Running, Role: LEADER
I20260812 06:18:59.944653  1046 sys_catalog.cc:565] T 00000000000000000000000000000000 P 0facc64c120c4ab3b9f59e9fbad399af [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:59.944801  1049 consensus_queue.cc:237] T 00000000000000000000000000000000 P 0facc64c120c4ab3b9f59e9fbad399af [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: "0facc64c120c4ab3b9f59e9fbad399af" member_type: VOTER }
I20260812 06:18:59.945349  1051 sys_catalog.cc:455] T 00000000000000000000000000000000 P 0facc64c120c4ab3b9f59e9fbad399af [sys.catalog]: SysCatalogTable state changed. Reason: New leader 0facc64c120c4ab3b9f59e9fbad399af. Latest consensus state: current_term: 1 leader_uuid: "0facc64c120c4ab3b9f59e9fbad399af" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0facc64c120c4ab3b9f59e9fbad399af" member_type: VOTER } }
I20260812 06:18:59.945523  1051 sys_catalog.cc:458] T 00000000000000000000000000000000 P 0facc64c120c4ab3b9f59e9fbad399af [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:59.945649  1050 sys_catalog.cc:455] T 00000000000000000000000000000000 P 0facc64c120c4ab3b9f59e9fbad399af [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "0facc64c120c4ab3b9f59e9fbad399af" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0facc64c120c4ab3b9f59e9fbad399af" member_type: VOTER } }
I20260812 06:18:59.945780  1050 sys_catalog.cc:458] T 00000000000000000000000000000000 P 0facc64c120c4ab3b9f59e9fbad399af [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:59.946188  1060 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:59.946908  1060 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:59.947151   757 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:59.949064  1060 catalog_manager.cc:1383] Generated new cluster ID: ae191c694fee4283bcad4dad76cc3d06
I20260812 06:18:59.949132  1060 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:59.957270  1060 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:59.957909  1060 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:59.963145  1060 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 0facc64c120c4ab3b9f59e9fbad399af: Generated new TSK 0
I20260812 06:18:59.963351  1060 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:59.980052   757 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:59.982650  1071 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:59.982643  1073 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:59.982788  1070 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:59.983006   757 server_base.cc:1061] running on GCE node
I20260812 06:18:59.983304   757 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:59.983352   757 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:59.983369   757 hybrid_clock.cc:648] HybridClock initialized: now 1786515539983369 us; error 0 us; skew 500 ppm
I20260812 06:18:59.984328   757 webserver.cc:533] Webserver started at http://127.0.189.65:43403/ using document root <none> and password file <none>
I20260812 06:18:59.984481   757 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:59.984527   757 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:59.984647   757 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:59.985065   757 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534140020-757-0/minicluster-data/ts-0-root/instance:
uuid: "5ae7e01b2cde410b81ca5ba4b9774efc"
format_stamp: "Formatted at 2026-08-12 06:18:59 on dist-test-slave-rgb1"
I20260812 06:18:59.986670   757 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:59.987869  1078 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:59.988240   757 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:59.988317   757 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534140020-757-0/minicluster-data/ts-0-root
uuid: "5ae7e01b2cde410b81ca5ba4b9774efc"
format_stamp: "Formatted at 2026-08-12 06:18:59 on dist-test-slave-rgb1"
I20260812 06:18:59.988426   757 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534140020-757-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534140020-757-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534140020-757-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:00.006597   757 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:00.007284   757 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:00.007642   757 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:00.008170   757 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:00.008239   757 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:00.008307   757 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:00.008365   757 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:00.015326   757 rpc_server.cc:307] RPC server started. Bound to: 127.0.189.65:35399
I20260812 06:19:00.017714  1150 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.0.189.65:35399 every 8 connection(s)
I20260812 06:19:00.031194  1152 heartbeater.cc:344] Connected to a master server at 127.0.189.126:39507
I20260812 06:19:00.031371  1152 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:00.031783  1152 heartbeater.cc:507] Master 127.0.189.126:39507 requested a full tablet report, sending...
I20260812 06:19:00.032764   757 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.016339103s
I20260812 06:19:00.032765  1004 ts_manager.cc:194] Registered new tserver with Master: 5ae7e01b2cde410b81ca5ba4b9774efc (127.0.189.65:35399)
I20260812 06:19:00.033960  1004 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:51304
I20260812 06:19:00.043097  1004 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:51312:
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:00.054981  1109 tablet_service.cc:1511] Processing CreateTablet for tablet c146d492824c47bfbb4d353d8b537a45 (DEFAULT_TABLE table=heavy-update-compaction-test [id=0566be8fd5ae4fb087e5d31b76c15e21]), partition=
I20260812 06:19:00.055441  1109 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet c146d492824c47bfbb4d353d8b537a45. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:00.058933  1167 tablet_bootstrap.cc:492] T c146d492824c47bfbb4d353d8b537a45 P 5ae7e01b2cde410b81ca5ba4b9774efc: Bootstrap starting.
I20260812 06:19:00.060740  1167 tablet_bootstrap.cc:654] T c146d492824c47bfbb4d353d8b537a45 P 5ae7e01b2cde410b81ca5ba4b9774efc: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:00.062503  1167 tablet_bootstrap.cc:492] T c146d492824c47bfbb4d353d8b537a45 P 5ae7e01b2cde410b81ca5ba4b9774efc: No bootstrap required, opened a new log
I20260812 06:19:00.062844  1167 ts_tablet_manager.cc:1403] T c146d492824c47bfbb4d353d8b537a45 P 5ae7e01b2cde410b81ca5ba4b9774efc: Time spent bootstrapping tablet: real 0.004s	user 0.000s	sys 0.003s
I20260812 06:19:00.063416  1167 raft_consensus.cc:359] T c146d492824c47bfbb4d353d8b537a45 P 5ae7e01b2cde410b81ca5ba4b9774efc [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5ae7e01b2cde410b81ca5ba4b9774efc" member_type: VOTER last_known_addr { host: "127.0.189.65" port: 35399 } }
I20260812 06:19:00.063525  1167 raft_consensus.cc:385] T c146d492824c47bfbb4d353d8b537a45 P 5ae7e01b2cde410b81ca5ba4b9774efc [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:00.063551  1167 raft_consensus.cc:740] T c146d492824c47bfbb4d353d8b537a45 P 5ae7e01b2cde410b81ca5ba4b9774efc [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 5ae7e01b2cde410b81ca5ba4b9774efc, State: Initialized, Role: FOLLOWER
I20260812 06:19:00.063723  1167 consensus_queue.cc:260] T c146d492824c47bfbb4d353d8b537a45 P 5ae7e01b2cde410b81ca5ba4b9774efc [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: "5ae7e01b2cde410b81ca5ba4b9774efc" member_type: VOTER last_known_addr { host: "127.0.189.65" port: 35399 } }
I20260812 06:19:00.063807  1167 raft_consensus.cc:399] T c146d492824c47bfbb4d353d8b537a45 P 5ae7e01b2cde410b81ca5ba4b9774efc [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:00.063844  1167 raft_consensus.cc:493] T c146d492824c47bfbb4d353d8b537a45 P 5ae7e01b2cde410b81ca5ba4b9774efc [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:00.063879  1167 raft_consensus.cc:3060] T c146d492824c47bfbb4d353d8b537a45 P 5ae7e01b2cde410b81ca5ba4b9774efc [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:00.064953  1167 raft_consensus.cc:515] T c146d492824c47bfbb4d353d8b537a45 P 5ae7e01b2cde410b81ca5ba4b9774efc [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5ae7e01b2cde410b81ca5ba4b9774efc" member_type: VOTER last_known_addr { host: "127.0.189.65" port: 35399 } }
I20260812 06:19:00.065101  1167 leader_election.cc:304] T c146d492824c47bfbb4d353d8b537a45 P 5ae7e01b2cde410b81ca5ba4b9774efc [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: 5ae7e01b2cde410b81ca5ba4b9774efc; no voters: 
I20260812 06:19:00.065351  1167 leader_election.cc:290] T c146d492824c47bfbb4d353d8b537a45 P 5ae7e01b2cde410b81ca5ba4b9774efc [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:00.065548  1169 raft_consensus.cc:2804] T c146d492824c47bfbb4d353d8b537a45 P 5ae7e01b2cde410b81ca5ba4b9774efc [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:00.065694  1167 ts_tablet_manager.cc:1434] T c146d492824c47bfbb4d353d8b537a45 P 5ae7e01b2cde410b81ca5ba4b9774efc: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:19:00.065725  1152 heartbeater.cc:499] Master 127.0.189.126:39507 was elected leader, sending a full tablet report...
I20260812 06:19:00.066133  1169 raft_consensus.cc:697] T c146d492824c47bfbb4d353d8b537a45 P 5ae7e01b2cde410b81ca5ba4b9774efc [term 1 LEADER]: Becoming Leader. State: Replica: 5ae7e01b2cde410b81ca5ba4b9774efc, State: Running, Role: LEADER
I20260812 06:19:00.066373  1169 consensus_queue.cc:237] T c146d492824c47bfbb4d353d8b537a45 P 5ae7e01b2cde410b81ca5ba4b9774efc [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: "5ae7e01b2cde410b81ca5ba4b9774efc" member_type: VOTER last_known_addr { host: "127.0.189.65" port: 35399 } }
I20260812 06:19:00.067967  1004 catalog_manager.cc:5719] T c146d492824c47bfbb4d353d8b537a45 P 5ae7e01b2cde410b81ca5ba4b9774efc reported cstate change: term changed from 0 to 1, leader changed from <none> to 5ae7e01b2cde410b81ca5ba4b9774efc (127.0.189.65). New cstate: current_term: 1 leader_uuid: "5ae7e01b2cde410b81ca5ba4b9774efc" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5ae7e01b2cde410b81ca5ba4b9774efc" member_type: VOTER last_known_addr { host: "127.0.189.65" port: 35399 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:00.130081   757 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.056s	user 0.013s	sys 0.011s
I20260812 06:19:00.268234  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling FlushMRSOp(c146d492824c47bfbb4d353d8b537a45): perf score=15.086190
I20260812 06:19:00.426707  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: FlushMRSOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.158s	user 0.115s	sys 0.033s Metrics: {"bytes_written":12307491,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":45,"dirs.run_cpu_time_us":223,"dirs.run_wall_time_us":1158,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":38366,"lbm_writes_lt_1ms":657,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"update_count":1500}
I20260812 06:19:00.427706  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling LogGCOp(c146d492824c47bfbb4d353d8b537a45): free 20290830 bytes of WAL
I20260812 06:19:00.427992  1085 log_reader.cc:385] T c146d492824c47bfbb4d353d8b537a45: removed 2 log segments from log reader
I20260812 06:19:00.428040  1085 log.cc:1079] T c146d492824c47bfbb4d353d8b537a45 P 5ae7e01b2cde410b81ca5ba4b9774efc: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534140020-757-0/minicluster-data/ts-0-root/wals/c146d492824c47bfbb4d353d8b537a45/wal-000000001 (ops 1-6)
I20260812 06:19:00.428078  1085 log.cc:1079] T c146d492824c47bfbb4d353d8b537a45 P 5ae7e01b2cde410b81ca5ba4b9774efc: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534140020-757-0/minicluster-data/ts-0-root/wals/c146d492824c47bfbb4d353d8b537a45/wal-000000002 (ops 7-10)
I20260812 06:19:00.432291  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: LogGCOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.004s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:19:00.432802  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45): perf score=2.188937
I20260812 06:19:00.457610  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.025s	user 0.011s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6479,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:00.458221  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling MajorDeltaCompactionOp(c146d492824c47bfbb4d353d8b537a45): perf score=1.000000
I20260812 06:19:00.628875  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: MajorDeltaCompactionOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.170s	user 0.101s	sys 0.069s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":932,"lbm_read_time_us":11826,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25503,"lbm_writes_lt_1ms":443,"mutex_wait_us":22,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4736,"thread_start_us":357,"threads_started":5,"update_count":2000}
I20260812 06:19:00.629595  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45): perf score=11.118625
I20260812 06:19:00.661721  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.032s	user 0.016s	sys 0.015s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":13994,"lbm_writes_lt_1ms":313,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":1550}
I20260812 06:19:00.662904  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling UndoDeltaBlockGCOp(c146d492824c47bfbb4d353d8b537a45): 12308960 bytes on disk
I20260812 06:19:00.663623  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: UndoDeltaBlockGCOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":111,"lbm_reads_lt_1ms":4}
I20260812 06:19:00.664264  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45): perf score=2.188937
I20260812 06:19:00.696856  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.032s	user 0.019s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6913,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:00.697377  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45): perf score=2.188937
I20260812 06:19:00.710987  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.013s	user 0.004s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4843,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:00.712051  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling MajorDeltaCompactionOp(c146d492824c47bfbb4d353d8b537a45): perf score=1.000000
I20260812 06:19:00.886710  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: MajorDeltaCompactionOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.174s	user 0.139s	sys 0.035s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733833,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":404,"lbm_read_time_us":11481,"lbm_reads_lt_1ms":573,"lbm_write_time_us":33997,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3200,"update_count":2500}
I20260812 06:19:00.887702  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45): perf score=11.118625
I20260812 06:19:00.934279  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.046s	user 0.037s	sys 0.008s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":20576,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:00.935038  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45): perf score=2.188937
I20260812 06:19:00.952726  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.017s	user 0.017s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6918,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:00.953210  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling MajorDeltaCompactionOp(c146d492824c47bfbb4d353d8b537a45): perf score=1.000000
I20260812 06:19:01.096159  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: MajorDeltaCompactionOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.143s	user 0.128s	sys 0.011s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631303,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"lbm_read_time_us":10191,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27300,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6400,"update_count":2000}
I20260812 06:19:01.096752  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45): perf score=10.126437
I20260812 06:19:01.146346  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.049s	user 0.028s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18816,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:01.147208  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45): perf score=2.188937
I20260812 06:19:01.159583  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.012s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4668,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:01.160197  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling MajorDeltaCompactionOp(c146d492824c47bfbb4d353d8b537a45): perf score=1.000000
I20260812 06:19:01.287842  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: MajorDeltaCompactionOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.127s	user 0.099s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":734,"lbm_read_time_us":8971,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24742,"lbm_writes_lt_1ms":443,"mutex_wait_us":21,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":23808,"update_count":2000}
I20260812 06:19:01.288641  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45): perf score=10.126437
I20260812 06:19:01.349699  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.061s	user 0.033s	sys 0.016s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":18571,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:01.350359  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45): perf score=2.188937
I20260812 06:19:01.365183  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.015s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5641,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:01.365747  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling MajorDeltaCompactionOp(c146d492824c47bfbb4d353d8b537a45): perf score=1.000000
I20260812 06:19:01.534054  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: MajorDeltaCompactionOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.168s	user 0.132s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631314,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":282,"lbm_read_time_us":13386,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26920,"lbm_writes_lt_1ms":443,"mutex_wait_us":116,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2000}
I20260812 06:19:01.534739  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45): perf score=10.126437
I20260812 06:19:01.583292  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.048s	user 0.026s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17522,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:01.583889  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45): perf score=2.188937
I20260812 06:19:01.596387  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4745,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:01.597159  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling MajorDeltaCompactionOp(c146d492824c47bfbb4d353d8b537a45): perf score=1.000000
I20260812 06:19:01.735879  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: MajorDeltaCompactionOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.138s	user 0.125s	sys 0.013s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1147,"lbm_read_time_us":8835,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26102,"lbm_writes_lt_1ms":443,"mutex_wait_us":316,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:01.736719  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45): perf score=10.126437
I20260812 06:19:01.796943  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.060s	user 0.025s	sys 0.021s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19949,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:19:01.797472  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45): perf score=2.188937
I20260812 06:19:01.810612  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.013s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4816,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:01.811113  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling FlushMRSOp(c146d492824c47bfbb4d353d8b537a45): perf score=1.000000
I20260812 06:19:01.851056  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: FlushMRSOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.040s	user 0.031s	sys 0.005s Metrics: {"bytes_written":1193504,"cfile_init":1,"dirs.queue_time_us":2297,"dirs.run_cpu_time_us":346,"dirs.run_wall_time_us":1709,"drs_written":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2435,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:19:01.852059  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling LogGCOp(c146d492824c47bfbb4d353d8b537a45): free 112239310 bytes of WAL
I20260812 06:19:01.852368  1085 log_reader.cc:385] T c146d492824c47bfbb4d353d8b537a45: removed 11 log segments from log reader
I20260812 06:19:01.852417  1085 log.cc:1079] T c146d492824c47bfbb4d353d8b537a45 P 5ae7e01b2cde410b81ca5ba4b9774efc: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534140020-757-0/minicluster-data/ts-0-root/wals/c146d492824c47bfbb4d353d8b537a45/wal-000000003 (ops 11-15)
I20260812 06:19:01.852453  1085 log.cc:1079] T c146d492824c47bfbb4d353d8b537a45 P 5ae7e01b2cde410b81ca5ba4b9774efc: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534140020-757-0/minicluster-data/ts-0-root/wals/c146d492824c47bfbb4d353d8b537a45/wal-000000004 (ops 16-20)
I20260812 06:19:01.852521  1085 log.cc:1079] T c146d492824c47bfbb4d353d8b537a45 P 5ae7e01b2cde410b81ca5ba4b9774efc: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534140020-757-0/minicluster-data/ts-0-root/wals/c146d492824c47bfbb4d353d8b537a45/wal-000000005 (ops 21-25)
I20260812 06:19:01.852625  1085 log.cc:1079] T c146d492824c47bfbb4d353d8b537a45 P 5ae7e01b2cde410b81ca5ba4b9774efc: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534140020-757-0/minicluster-data/ts-0-root/wals/c146d492824c47bfbb4d353d8b537a45/wal-000000006 (ops 26-30)
I20260812 06:19:01.852694  1085 log.cc:1079] T c146d492824c47bfbb4d353d8b537a45 P 5ae7e01b2cde410b81ca5ba4b9774efc: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534140020-757-0/minicluster-data/ts-0-root/wals/c146d492824c47bfbb4d353d8b537a45/wal-000000007 (ops 31-35)
I20260812 06:19:01.852720  1085 log.cc:1079] T c146d492824c47bfbb4d353d8b537a45 P 5ae7e01b2cde410b81ca5ba4b9774efc: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534140020-757-0/minicluster-data/ts-0-root/wals/c146d492824c47bfbb4d353d8b537a45/wal-000000008 (ops 36-40)
I20260812 06:19:01.852779  1085 log.cc:1079] T c146d492824c47bfbb4d353d8b537a45 P 5ae7e01b2cde410b81ca5ba4b9774efc: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534140020-757-0/minicluster-data/ts-0-root/wals/c146d492824c47bfbb4d353d8b537a45/wal-000000009 (ops 41-45)
I20260812 06:19:01.852821  1085 log.cc:1079] T c146d492824c47bfbb4d353d8b537a45 P 5ae7e01b2cde410b81ca5ba4b9774efc: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534140020-757-0/minicluster-data/ts-0-root/wals/c146d492824c47bfbb4d353d8b537a45/wal-000000010 (ops 46-50)
I20260812 06:19:01.852867  1085 log.cc:1079] T c146d492824c47bfbb4d353d8b537a45 P 5ae7e01b2cde410b81ca5ba4b9774efc: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534140020-757-0/minicluster-data/ts-0-root/wals/c146d492824c47bfbb4d353d8b537a45/wal-000000011 (ops 51-54)
I20260812 06:19:01.852909  1085 log.cc:1079] T c146d492824c47bfbb4d353d8b537a45 P 5ae7e01b2cde410b81ca5ba4b9774efc: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534140020-757-0/minicluster-data/ts-0-root/wals/c146d492824c47bfbb4d353d8b537a45/wal-000000012 (ops 55-59)
I20260812 06:19:01.852948  1085 log.cc:1079] T c146d492824c47bfbb4d353d8b537a45 P 5ae7e01b2cde410b81ca5ba4b9774efc: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534140020-757-0/minicluster-data/ts-0-root/wals/c146d492824c47bfbb4d353d8b537a45/wal-000000013 (ops 60-64)
I20260812 06:19:01.884692  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: LogGCOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.032s	user 0.000s	sys 0.032s Metrics: {}
I20260812 06:19:01.885226  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling UndoDeltaBlockGCOp(c146d492824c47bfbb4d353d8b537a45): 463 bytes on disk
I20260812 06:19:01.885738  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: UndoDeltaBlockGCOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":80,"lbm_reads_lt_1ms":4}
I20260812 06:19:01.886632  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45): perf score=2.188937
I20260812 06:19:01.915525  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.029s	user 0.015s	sys 0.007s Metrics: {"bytes_written":4225731,"delete_count":0,"lbm_write_time_us":10332,"lbm_writes_lt_1ms":106,"reinsert_count":0,"update_count":515}
I20260812 06:19:01.916057  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45): perf score=2.188937
I20260812 06:19:01.928141  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":3979584,"delete_count":0,"lbm_write_time_us":4537,"lbm_writes_lt_1ms":100,"reinsert_count":0,"update_count":485}
I20260812 06:19:01.928754  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling MajorDeltaCompactionOp(c146d492824c47bfbb4d353d8b537a45): perf score=1.000000
I20260812 06:19:02.156314  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: MajorDeltaCompactionOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.227s	user 0.182s	sys 0.045s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836371,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":821,"lbm_read_time_us":13860,"lbm_reads_lt_1ms":674,"lbm_write_time_us":48189,"lbm_writes_lt_1ms":643,"mutex_wait_us":63,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":12800,"thread_start_us":92,"threads_started":1,"update_count":3000}
I20260812 06:19:02.157094  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45): perf score=14.095187
I20260812 06:19:02.229521  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.072s	user 0.048s	sys 0.023s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":30971,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:02.230111  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45): perf score=2.188937
I20260812 06:19:02.258315  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.028s	user 0.008s	sys 0.008s Metrics: {"bytes_written":4143684,"delete_count":0,"lbm_write_time_us":6410,"lbm_writes_lt_1ms":104,"reinsert_count":0,"update_count":505}
I20260812 06:19:02.258945  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45): perf score=2.188937
I20260812 06:19:02.272991  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.014s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4061634,"delete_count":0,"lbm_write_time_us":5275,"lbm_writes_lt_1ms":102,"reinsert_count":0,"update_count":495}
I20260812 06:19:02.273559  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling MajorDeltaCompactionOp(c146d492824c47bfbb4d353d8b537a45): perf score=1.000000
I20260812 06:19:02.505368  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: MajorDeltaCompactionOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.232s	user 0.166s	sys 0.055s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28836255,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1231,"lbm_read_time_us":14722,"lbm_reads_lt_1ms":673,"lbm_write_time_us":48315,"lbm_writes_lt_1ms":643,"mutex_wait_us":484,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":322944,"update_count":3000}
I20260812 06:19:02.506136  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45): perf score=14.095187
I20260812 06:19:02.569504  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.063s	user 0.044s	sys 0.017s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":27755,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:02.570161  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45): perf score=2.188937
I20260812 06:19:02.583689  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.013s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5018,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:02.584659  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling MajorDeltaCompactionOp(c146d492824c47bfbb4d353d8b537a45): perf score=1.000000
I20260812 06:19:02.789723  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: MajorDeltaCompactionOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.205s	user 0.159s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733722,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":428,"lbm_read_time_us":12028,"lbm_reads_lt_1ms":572,"lbm_write_time_us":37033,"lbm_writes_lt_1ms":543,"mutex_wait_us":3,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":404864,"update_count":2500}
I20260812 06:19:02.790531  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45): perf score=10.126437
I20260812 06:19:02.839010  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.048s	user 0.022s	sys 0.024s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":21722,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:02.839641  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45): perf score=2.188937
I20260812 06:19:02.862273  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.022s	user 0.012s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6197,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:02.862906  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling MajorDeltaCompactionOp(c146d492824c47bfbb4d353d8b537a45): perf score=1.000000
I20260812 06:19:03.018266  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: MajorDeltaCompactionOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.155s	user 0.115s	sys 0.039s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1124,"lbm_read_time_us":8078,"lbm_reads_lt_1ms":464,"lbm_write_time_us":32654,"lbm_writes_lt_1ms":443,"mutex_wait_us":465,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:03.019200  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45): perf score=10.126437
I20260812 06:19:03.066735  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.046s	user 0.016s	sys 0.017s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16141,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:03.067337  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45): perf score=2.188937
I20260812 06:19:03.083184  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.016s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5822,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:03.084317  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling MajorDeltaCompactionOp(c146d492824c47bfbb4d353d8b537a45): perf score=1.000000
I20260812 06:19:03.244506  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: MajorDeltaCompactionOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.160s	user 0.111s	sys 0.044s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":575,"lbm_read_time_us":10000,"lbm_reads_lt_1ms":472,"lbm_write_time_us":30279,"lbm_writes_lt_1ms":443,"mutex_wait_us":76,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":24832,"update_count":2000}
I20260812 06:19:03.245443  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45): perf score=11.118625
I20260812 06:19:03.296109  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.050s	user 0.035s	sys 0.012s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":18126,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:03.296746  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45): perf score=2.188937
I20260812 06:19:03.322588  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.026s	user 0.008s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":7523,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:03.323104  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45): perf score=2.188937
I20260812 06:19:03.334779  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.012s	user 0.004s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4405,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:03.335395  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling MajorDeltaCompactionOp(c146d492824c47bfbb4d353d8b537a45): perf score=1.000000
I20260812 06:19:03.549997  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: MajorDeltaCompactionOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.214s	user 0.162s	sys 0.052s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733836,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1869,"lbm_read_time_us":14611,"lbm_reads_lt_1ms":573,"lbm_write_time_us":38508,"lbm_writes_lt_1ms":543,"mutex_wait_us":539,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":30720,"update_count":2500}
I20260812 06:19:03.550906  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45): perf score=14.095187
I20260812 06:19:03.612233  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.061s	user 0.026s	sys 0.031s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":22179,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:03.613201  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45): perf score=2.188937
I20260812 06:19:03.633100  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.020s	user 0.007s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7748,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:03.633755  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling FlushMRSOp(c146d492824c47bfbb4d353d8b537a45): perf score=1.000000
I20260812 06:19:03.673540  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: FlushMRSOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.040s	user 0.035s	sys 0.000s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":115,"dirs.run_cpu_time_us":285,"dirs.run_wall_time_us":1583,"drs_written":1,"lbm_read_time_us":65,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2887,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:19:03.674428  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling LogGCOp(c146d492824c47bfbb4d353d8b537a45): free 133477432 bytes of WAL
I20260812 06:19:03.674695  1085 log_reader.cc:385] T c146d492824c47bfbb4d353d8b537a45: removed 13 log segments from log reader
I20260812 06:19:03.674731  1085 log.cc:1079] T c146d492824c47bfbb4d353d8b537a45 P 5ae7e01b2cde410b81ca5ba4b9774efc: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534140020-757-0/minicluster-data/ts-0-root/wals/c146d492824c47bfbb4d353d8b537a45/wal-000000014 (ops 65-69)
I20260812 06:19:03.674791  1085 log.cc:1079] T c146d492824c47bfbb4d353d8b537a45 P 5ae7e01b2cde410b81ca5ba4b9774efc: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534140020-757-0/minicluster-data/ts-0-root/wals/c146d492824c47bfbb4d353d8b537a45/wal-000000015 (ops 70-74)
I20260812 06:19:03.674853  1085 log.cc:1079] T c146d492824c47bfbb4d353d8b537a45 P 5ae7e01b2cde410b81ca5ba4b9774efc: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534140020-757-0/minicluster-data/ts-0-root/wals/c146d492824c47bfbb4d353d8b537a45/wal-000000016 (ops 75-79)
I20260812 06:19:03.674876  1085 log.cc:1079] T c146d492824c47bfbb4d353d8b537a45 P 5ae7e01b2cde410b81ca5ba4b9774efc: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534140020-757-0/minicluster-data/ts-0-root/wals/c146d492824c47bfbb4d353d8b537a45/wal-000000017 (ops 80-84)
I20260812 06:19:03.674916  1085 log.cc:1079] T c146d492824c47bfbb4d353d8b537a45 P 5ae7e01b2cde410b81ca5ba4b9774efc: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534140020-757-0/minicluster-data/ts-0-root/wals/c146d492824c47bfbb4d353d8b537a45/wal-000000018 (ops 85-89)
I20260812 06:19:03.674962  1085 log.cc:1079] T c146d492824c47bfbb4d353d8b537a45 P 5ae7e01b2cde410b81ca5ba4b9774efc: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534140020-757-0/minicluster-data/ts-0-root/wals/c146d492824c47bfbb4d353d8b537a45/wal-000000019 (ops 90-94)
I20260812 06:19:03.674995  1085 log.cc:1079] T c146d492824c47bfbb4d353d8b537a45 P 5ae7e01b2cde410b81ca5ba4b9774efc: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534140020-757-0/minicluster-data/ts-0-root/wals/c146d492824c47bfbb4d353d8b537a45/wal-000000020 (ops 95-99)
I20260812 06:19:03.675014  1085 log.cc:1079] T c146d492824c47bfbb4d353d8b537a45 P 5ae7e01b2cde410b81ca5ba4b9774efc: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534140020-757-0/minicluster-data/ts-0-root/wals/c146d492824c47bfbb4d353d8b537a45/wal-000000021 (ops 100-104)
I20260812 06:19:03.675030  1085 log.cc:1079] T c146d492824c47bfbb4d353d8b537a45 P 5ae7e01b2cde410b81ca5ba4b9774efc: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534140020-757-0/minicluster-data/ts-0-root/wals/c146d492824c47bfbb4d353d8b537a45/wal-000000022 (ops 105-109)
I20260812 06:19:03.675047  1085 log.cc:1079] T c146d492824c47bfbb4d353d8b537a45 P 5ae7e01b2cde410b81ca5ba4b9774efc: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534140020-757-0/minicluster-data/ts-0-root/wals/c146d492824c47bfbb4d353d8b537a45/wal-000000023 (ops 110-114)
I20260812 06:19:03.675064  1085 log.cc:1079] T c146d492824c47bfbb4d353d8b537a45 P 5ae7e01b2cde410b81ca5ba4b9774efc: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534140020-757-0/minicluster-data/ts-0-root/wals/c146d492824c47bfbb4d353d8b537a45/wal-000000024 (ops 115-119)
I20260812 06:19:03.675081  1085 log.cc:1079] T c146d492824c47bfbb4d353d8b537a45 P 5ae7e01b2cde410b81ca5ba4b9774efc: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534140020-757-0/minicluster-data/ts-0-root/wals/c146d492824c47bfbb4d353d8b537a45/wal-000000025 (ops 120-124)
I20260812 06:19:03.675136  1085 log.cc:1079] T c146d492824c47bfbb4d353d8b537a45 P 5ae7e01b2cde410b81ca5ba4b9774efc: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534140020-757-0/minicluster-data/ts-0-root/wals/c146d492824c47bfbb4d353d8b537a45/wal-000000026 (ops 125-129)
I20260812 06:19:03.703363  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: LogGCOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.029s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:19:03.703833  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling UndoDeltaBlockGCOp(c146d492824c47bfbb4d353d8b537a45): 492 bytes on disk
I20260812 06:19:03.704293  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: UndoDeltaBlockGCOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4}
I20260812 06:19:03.704883  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45): perf score=2.188937
I20260812 06:19:03.725123  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.020s	user 0.009s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5168,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:03.726120  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45): perf score=2.188937
I20260812 06:19:03.742517  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.016s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5966,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:03.743187  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling MajorDeltaCompactionOp(c146d492824c47bfbb4d353d8b537a45): perf score=1.000000
I20260812 06:19:04.005185  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: MajorDeltaCompactionOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.262s	user 0.199s	sys 0.060s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32938784,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":601,"lbm_read_time_us":18783,"lbm_reads_lt_1ms":774,"lbm_write_time_us":43842,"lbm_writes_lt_1ms":743,"mutex_wait_us":60,"peak_mem_usage":87969044,"reinsert_count":0,"thread_start_us":89,"threads_started":1,"update_count":3500}
I20260812 06:19:04.005964  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45): perf score=15.087375
I20260812 06:19:04.064289  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.058s	user 0.046s	sys 0.008s Metrics: {"bytes_written":16820146,"delete_count":0,"lbm_write_time_us":26083,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:19:04.065055  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45): perf score=2.188937
I20260812 06:19:04.095821  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.030s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6185,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:04.096469  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45): perf score=2.188937
I20260812 06:19:04.115767  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.019s	user 0.007s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6840,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:04.116708  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling MajorDeltaCompactionOp(c146d492824c47bfbb4d353d8b537a45): perf score=1.000000
I20260812 06:19:04.323259  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: MajorDeltaCompactionOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.206s	user 0.158s	sys 0.048s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28836245,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":277,"lbm_read_time_us":15820,"lbm_reads_lt_1ms":673,"lbm_write_time_us":38119,"lbm_writes_lt_1ms":643,"mutex_wait_us":24,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":223488,"update_count":3000}
I20260812 06:19:04.323917  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45): perf score=14.095187
I20260812 06:19:04.375135  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.051s	user 0.037s	sys 0.012s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22389,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:04.376121  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45): perf score=2.188937
I20260812 06:19:04.390185  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5251,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:04.390789  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling MajorDeltaCompactionOp(c146d492824c47bfbb4d353d8b537a45): perf score=1.000000
I20260812 06:19:04.589352  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: MajorDeltaCompactionOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.198s	user 0.144s	sys 0.043s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":371,"lbm_read_time_us":10566,"lbm_reads_lt_1ms":572,"lbm_write_time_us":39722,"lbm_writes_lt_1ms":543,"mutex_wait_us":90,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4736,"update_count":2500}
I20260812 06:19:04.590047  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45): perf score=14.095187
I20260812 06:19:04.650029  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.060s	user 0.030s	sys 0.024s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":21943,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:04.650621  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling MajorDeltaCompactionOp(c146d492824c47bfbb4d353d8b537a45): perf score=1.000000
I20260812 06:19:04.813076  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: MajorDeltaCompactionOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.162s	user 0.118s	sys 0.044s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20631191,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":882,"lbm_read_time_us":11185,"lbm_reads_lt_1ms":463,"lbm_write_time_us":25599,"lbm_writes_lt_1ms":443,"mutex_wait_us":322,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":51072,"update_count":2000}
I20260812 06:19:04.813714  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45): perf score=14.095187
I20260812 06:19:04.881246  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.067s	user 0.035s	sys 0.032s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":28232,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:04.881943  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45): perf score=2.188937
I20260812 06:19:04.901001  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.018s	user 0.010s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7141,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:04.901554  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling MajorDeltaCompactionOp(c146d492824c47bfbb4d353d8b537a45): perf score=1.000000
I20260812 06:19:05.102511  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: MajorDeltaCompactionOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.200s	user 0.148s	sys 0.050s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":989,"lbm_read_time_us":14117,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33717,"lbm_writes_lt_1ms":543,"mutex_wait_us":73,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3840,"update_count":2500}
I20260812 06:19:05.103449  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45): perf score=14.095187
I20260812 06:19:05.163914  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.060s	user 0.032s	sys 0.025s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":26088,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:05.164697  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45): perf score=2.188937
I20260812 06:19:05.180516  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.016s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5571,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:05.181224  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling MajorDeltaCompactionOp(c146d492824c47bfbb4d353d8b537a45): perf score=1.000000
I20260812 06:19:05.370146  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: MajorDeltaCompactionOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.189s	user 0.141s	sys 0.034s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":885,"lbm_read_time_us":11348,"lbm_reads_lt_1ms":564,"lbm_write_time_us":35904,"lbm_writes_lt_1ms":543,"mutex_wait_us":329,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5760,"update_count":2500}
I20260812 06:19:05.371203  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45): perf score=14.095187
I20260812 06:19:05.453123  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.081s	user 0.057s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":36558,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:05.454115  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45): perf score=2.188937
I20260812 06:19:05.474941  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.020s	user 0.010s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7262,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:05.476382  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling FlushMRSOp(c146d492824c47bfbb4d353d8b537a45): perf score=1.000000
I20260812 06:19:05.529740  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: FlushMRSOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.053s	user 0.051s	sys 0.000s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":144,"dirs.run_cpu_time_us":377,"dirs.run_wall_time_us":2174,"drs_written":1,"lbm_read_time_us":140,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2703,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:05.531297  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling LogGCOp(c146d492824c47bfbb4d353d8b537a45): free 133024594 bytes of WAL
I20260812 06:19:05.531754  1085 log_reader.cc:385] T c146d492824c47bfbb4d353d8b537a45: removed 13 log segments from log reader
I20260812 06:19:05.531863  1085 log.cc:1079] T c146d492824c47bfbb4d353d8b537a45 P 5ae7e01b2cde410b81ca5ba4b9774efc: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534140020-757-0/minicluster-data/ts-0-root/wals/c146d492824c47bfbb4d353d8b537a45/wal-000000027 (ops 130-134)
I20260812 06:19:05.531997  1085 log.cc:1079] T c146d492824c47bfbb4d353d8b537a45 P 5ae7e01b2cde410b81ca5ba4b9774efc: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534140020-757-0/minicluster-data/ts-0-root/wals/c146d492824c47bfbb4d353d8b537a45/wal-000000028 (ops 135-139)
I20260812 06:19:05.532091  1085 log.cc:1079] T c146d492824c47bfbb4d353d8b537a45 P 5ae7e01b2cde410b81ca5ba4b9774efc: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534140020-757-0/minicluster-data/ts-0-root/wals/c146d492824c47bfbb4d353d8b537a45/wal-000000029 (ops 140-144)
I20260812 06:19:05.532155  1085 log.cc:1079] T c146d492824c47bfbb4d353d8b537a45 P 5ae7e01b2cde410b81ca5ba4b9774efc: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534140020-757-0/minicluster-data/ts-0-root/wals/c146d492824c47bfbb4d353d8b537a45/wal-000000030 (ops 145-149)
I20260812 06:19:05.532213  1085 log.cc:1079] T c146d492824c47bfbb4d353d8b537a45 P 5ae7e01b2cde410b81ca5ba4b9774efc: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534140020-757-0/minicluster-data/ts-0-root/wals/c146d492824c47bfbb4d353d8b537a45/wal-000000031 (ops 150-154)
I20260812 06:19:05.532290  1085 log.cc:1079] T c146d492824c47bfbb4d353d8b537a45 P 5ae7e01b2cde410b81ca5ba4b9774efc: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534140020-757-0/minicluster-data/ts-0-root/wals/c146d492824c47bfbb4d353d8b537a45/wal-000000032 (ops 155-159)
I20260812 06:19:05.532363  1085 log.cc:1079] T c146d492824c47bfbb4d353d8b537a45 P 5ae7e01b2cde410b81ca5ba4b9774efc: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534140020-757-0/minicluster-data/ts-0-root/wals/c146d492824c47bfbb4d353d8b537a45/wal-000000033 (ops 160-164)
I20260812 06:19:05.532401  1085 log.cc:1079] T c146d492824c47bfbb4d353d8b537a45 P 5ae7e01b2cde410b81ca5ba4b9774efc: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534140020-757-0/minicluster-data/ts-0-root/wals/c146d492824c47bfbb4d353d8b537a45/wal-000000034 (ops 165-169)
I20260812 06:19:05.532471  1085 log.cc:1079] T c146d492824c47bfbb4d353d8b537a45 P 5ae7e01b2cde410b81ca5ba4b9774efc: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534140020-757-0/minicluster-data/ts-0-root/wals/c146d492824c47bfbb4d353d8b537a45/wal-000000035 (ops 170-174)
I20260812 06:19:05.532548  1085 log.cc:1079] T c146d492824c47bfbb4d353d8b537a45 P 5ae7e01b2cde410b81ca5ba4b9774efc: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534140020-757-0/minicluster-data/ts-0-root/wals/c146d492824c47bfbb4d353d8b537a45/wal-000000036 (ops 175-179)
I20260812 06:19:05.532661  1085 log.cc:1079] T c146d492824c47bfbb4d353d8b537a45 P 5ae7e01b2cde410b81ca5ba4b9774efc: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534140020-757-0/minicluster-data/ts-0-root/wals/c146d492824c47bfbb4d353d8b537a45/wal-000000037 (ops 180-184)
I20260812 06:19:05.532727  1085 log.cc:1079] T c146d492824c47bfbb4d353d8b537a45 P 5ae7e01b2cde410b81ca5ba4b9774efc: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534140020-757-0/minicluster-data/ts-0-root/wals/c146d492824c47bfbb4d353d8b537a45/wal-000000038 (ops 185-188)
I20260812 06:19:05.532769  1085 log.cc:1079] T c146d492824c47bfbb4d353d8b537a45 P 5ae7e01b2cde410b81ca5ba4b9774efc: Deleting log segment in path: /tmp/dist-test-task6gviT8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534140020-757-0/minicluster-data/ts-0-root/wals/c146d492824c47bfbb4d353d8b537a45/wal-000000039 (ops 189-193)
I20260812 06:19:05.580333  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: LogGCOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.049s	user 0.000s	sys 0.045s Metrics: {}
I20260812 06:19:05.581420  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling UndoDeltaBlockGCOp(c146d492824c47bfbb4d353d8b537a45): 483 bytes on disk
I20260812 06:19:05.582607  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: UndoDeltaBlockGCOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":201,"lbm_reads_lt_1ms":4}
I20260812 06:19:05.584012  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45): perf score=2.188937
I20260812 06:19:05.647359  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.063s	user 0.026s	sys 0.021s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":12977,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:05.648468  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45): perf score=2.188937
I20260812 06:19:05.677397  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.028s	user 0.019s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":12032,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":102,"reinsert_count":0,"update_count":500}
I20260812 06:19:05.677994  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling MajorDeltaCompactionOp(c146d492824c47bfbb4d353d8b537a45): perf score=1.000000
I20260812 06:19:05.962158   757 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.832s	user 2.140s	sys 0.195s
I20260812 06:19:06.112886  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: MajorDeltaCompactionOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.435s	user 0.309s	sys 0.124s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32938784,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":2045,"lbm_read_time_us":36042,"lbm_reads_lt_1ms":770,"lbm_write_time_us":77532,"lbm_writes_lt_1ms":743,"mutex_wait_us":101,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":9728,"thread_start_us":938,"threads_started":7,"update_count":3500}
I20260812 06:19:06.114450  1154 maintenance_manager.cc:419] P 5ae7e01b2cde410b81ca5ba4b9774efc: Scheduling FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45): perf score=10.126437
I20260812 06:19:06.132637   757 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.170s	user 0.007s	sys 0.000s
I20260812 06:19:06.133639   757 tablet_server.cc:179] TabletServer@127.0.189.65:0 shutting down...
I20260812 06:19:06.181823  1085 maintenance_manager.cc:643] P 5ae7e01b2cde410b81ca5ba4b9774efc: FlushDeltaMemStoresOp(c146d492824c47bfbb4d353d8b537a45) complete. Timing: real 0.067s	user 0.049s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":28496,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:06.182951   757 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:06.183419   757 tablet_replica.cc:333] T c146d492824c47bfbb4d353d8b537a45 P 5ae7e01b2cde410b81ca5ba4b9774efc: stopping tablet replica
I20260812 06:19:06.183612   757 raft_consensus.cc:2243] T c146d492824c47bfbb4d353d8b537a45 P 5ae7e01b2cde410b81ca5ba4b9774efc [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:06.200762   757 raft_consensus.cc:2272] T c146d492824c47bfbb4d353d8b537a45 P 5ae7e01b2cde410b81ca5ba4b9774efc [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:06.207798   757 tablet_server.cc:196] TabletServer@127.0.189.65:0 shutdown complete.
I20260812 06:19:06.213276   757 master.cc:562] Master@127.0.189.126:39507 shutting down...
I20260812 06:19:06.219724   757 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 0facc64c120c4ab3b9f59e9fbad399af [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:06.220166   757 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 0facc64c120c4ab3b9f59e9fbad399af [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:06.220337   757 tablet_replica.cc:333] T 00000000000000000000000000000000 P 0facc64c120c4ab3b9f59e9fbad399af: stopping tablet replica
I20260812 06:19:06.234719   757 master.cc:584] Master@127.0.189.126:39507 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (6474 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (12216 ms total)

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