[==========] 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:16:53.443558  3933 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.3.215.126:45015
I20260812 06:16:53.444597  3933 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:16:53.445277  3933 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:53.452235  3945 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:16:53.452291  3933 server_base.cc:1061] running on GCE node
W20260812 06:16:53.452195  3948 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:16:53.452478  3944 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:16:53.453073  3933 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:53.453164  3933 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:16:53.453199  3933 hybrid_clock.cc:648] HybridClock initialized: now 1786515413453198 us; error 0 us; skew 500 ppm
I20260812 06:16:53.458240  3933 webserver.cc:533] Webserver started at http://127.3.215.126:42055/ using document root <none> and password file <none>
I20260812 06:16:53.458753  3933 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:53.458808  3933 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:53.459005  3933 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:53.460553  3933 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413432700-3933-0/minicluster-data/master-0-root/instance:
uuid: "0d9dcc994fdb4835aba90ad24fd0a468"
format_stamp: "Formatted at 2026-08-12 06:16:53 on dist-test-slave-2kcd"
I20260812 06:16:53.464033  3933 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.001s	sys 0.001s
I20260812 06:16:53.466090  3958 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:16:53.467089  3933 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:16:53.467219  3933 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413432700-3933-0/minicluster-data/master-0-root
uuid: "0d9dcc994fdb4835aba90ad24fd0a468"
format_stamp: "Formatted at 2026-08-12 06:16:53 on dist-test-slave-2kcd"
I20260812 06:16:53.467320  3933 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413432700-3933-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413432700-3933-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413432700-3933-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:16:53.483505  3933 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:53.485953  3933 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:16:53.488226  3933 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:53.498632  3933 rpc_server.cc:307] RPC server started. Bound to: 127.3.215.126:45015
I20260812 06:16:53.498687  4051 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.3.215.126:45015 every 8 connection(s)
I20260812 06:16:53.502677  4054 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:16:53.511560  4054 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 0d9dcc994fdb4835aba90ad24fd0a468: Bootstrap starting.
I20260812 06:16:53.514859  4054 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 0d9dcc994fdb4835aba90ad24fd0a468: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:53.516227  4054 log.cc:826] T 00000000000000000000000000000000 P 0d9dcc994fdb4835aba90ad24fd0a468: Log is configured to *not* fsync() on all Append() calls
I20260812 06:16:53.518721  4054 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 0d9dcc994fdb4835aba90ad24fd0a468: No bootstrap required, opened a new log
I20260812 06:16:53.523699  4054 raft_consensus.cc:359] T 00000000000000000000000000000000 P 0d9dcc994fdb4835aba90ad24fd0a468 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0d9dcc994fdb4835aba90ad24fd0a468" member_type: VOTER }
I20260812 06:16:53.523959  4054 raft_consensus.cc:385] T 00000000000000000000000000000000 P 0d9dcc994fdb4835aba90ad24fd0a468 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:53.524115  4054 raft_consensus.cc:740] T 00000000000000000000000000000000 P 0d9dcc994fdb4835aba90ad24fd0a468 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 0d9dcc994fdb4835aba90ad24fd0a468, State: Initialized, Role: FOLLOWER
I20260812 06:16:53.525028  4054 consensus_queue.cc:260] T 00000000000000000000000000000000 P 0d9dcc994fdb4835aba90ad24fd0a468 [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: "0d9dcc994fdb4835aba90ad24fd0a468" member_type: VOTER }
I20260812 06:16:53.525254  4054 raft_consensus.cc:399] T 00000000000000000000000000000000 P 0d9dcc994fdb4835aba90ad24fd0a468 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:53.525342  4054 raft_consensus.cc:493] T 00000000000000000000000000000000 P 0d9dcc994fdb4835aba90ad24fd0a468 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:53.525497  4054 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 0d9dcc994fdb4835aba90ad24fd0a468 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:53.526827  4054 raft_consensus.cc:515] T 00000000000000000000000000000000 P 0d9dcc994fdb4835aba90ad24fd0a468 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0d9dcc994fdb4835aba90ad24fd0a468" member_type: VOTER }
I20260812 06:16:53.527431  4054 leader_election.cc:304] T 00000000000000000000000000000000 P 0d9dcc994fdb4835aba90ad24fd0a468 [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: 0d9dcc994fdb4835aba90ad24fd0a468; no voters: 
I20260812 06:16:53.527860  4054 leader_election.cc:290] T 00000000000000000000000000000000 P 0d9dcc994fdb4835aba90ad24fd0a468 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:53.528004  4058 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 0d9dcc994fdb4835aba90ad24fd0a468 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:53.528288  4058 raft_consensus.cc:697] T 00000000000000000000000000000000 P 0d9dcc994fdb4835aba90ad24fd0a468 [term 1 LEADER]: Becoming Leader. State: Replica: 0d9dcc994fdb4835aba90ad24fd0a468, State: Running, Role: LEADER
I20260812 06:16:53.528832  4058 consensus_queue.cc:237] T 00000000000000000000000000000000 P 0d9dcc994fdb4835aba90ad24fd0a468 [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: "0d9dcc994fdb4835aba90ad24fd0a468" member_type: VOTER }
I20260812 06:16:53.529179  4054 sys_catalog.cc:565] T 00000000000000000000000000000000 P 0d9dcc994fdb4835aba90ad24fd0a468 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:53.531178  4061 sys_catalog.cc:455] T 00000000000000000000000000000000 P 0d9dcc994fdb4835aba90ad24fd0a468 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 0d9dcc994fdb4835aba90ad24fd0a468. Latest consensus state: current_term: 1 leader_uuid: "0d9dcc994fdb4835aba90ad24fd0a468" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0d9dcc994fdb4835aba90ad24fd0a468" member_type: VOTER } }
I20260812 06:16:53.531219  4060 sys_catalog.cc:455] T 00000000000000000000000000000000 P 0d9dcc994fdb4835aba90ad24fd0a468 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "0d9dcc994fdb4835aba90ad24fd0a468" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0d9dcc994fdb4835aba90ad24fd0a468" member_type: VOTER } }
I20260812 06:16:53.531322  4061 sys_catalog.cc:458] T 00000000000000000000000000000000 P 0d9dcc994fdb4835aba90ad24fd0a468 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:53.531337  4060 sys_catalog.cc:458] T 00000000000000000000000000000000 P 0d9dcc994fdb4835aba90ad24fd0a468 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:53.531744  4080 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:53.531971  3933 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:53.534739  4080 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:53.540741  4080 catalog_manager.cc:1383] Generated new cluster ID: e801eea84aa44544ae5f9c5f5838a8e0
I20260812 06:16:53.540848  4080 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:53.568425  4080 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:53.569410  4080 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:53.575430  4080 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 0d9dcc994fdb4835aba90ad24fd0a468: Generated new TSK 0
I20260812 06:16:53.576035  4080 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:53.597306  3933 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:53.600126  4092 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:16:53.600204  3933 server_base.cc:1061] running on GCE node
W20260812 06:16:53.600143  4088 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:16:53.600292  4089 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:16:53.600572  3933 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:53.600617  3933 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:16:53.600632  3933 hybrid_clock.cc:648] HybridClock initialized: now 1786515413600633 us; error 0 us; skew 500 ppm
I20260812 06:16:53.601577  3933 webserver.cc:533] Webserver started at http://127.3.215.65:44719/ using document root <none> and password file <none>
I20260812 06:16:53.601755  3933 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:53.601814  3933 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:53.601940  3933 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:53.602336  3933 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413432700-3933-0/minicluster-data/ts-0-root/instance:
uuid: "18ec33df405d436c96c248fe5ff6950d"
format_stamp: "Formatted at 2026-08-12 06:16:53 on dist-test-slave-2kcd"
I20260812 06:16:53.603870  3933 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:16:53.604882  4109 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:16:53.605178  3933 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:53.605258  3933 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413432700-3933-0/minicluster-data/ts-0-root
uuid: "18ec33df405d436c96c248fe5ff6950d"
format_stamp: "Formatted at 2026-08-12 06:16:53 on dist-test-slave-2kcd"
I20260812 06:16:53.605309  3933 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413432700-3933-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413432700-3933-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413432700-3933-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:16:53.622015  3933 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:53.622432  3933 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:53.622933  3933 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:53.623769  3933 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:53.623844  3933 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:53.623932  3933 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:53.623975  3933 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:53.631098  3933 rpc_server.cc:307] RPC server started. Bound to: 127.3.215.65:39593
I20260812 06:16:53.631171  4213 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.3.215.65:39593 every 8 connection(s)
I20260812 06:16:53.641944  4216 heartbeater.cc:344] Connected to a master server at 127.3.215.126:45015
I20260812 06:16:53.642222  4216 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:53.642701  4216 heartbeater.cc:507] Master 127.3.215.126:45015 requested a full tablet report, sending...
I20260812 06:16:53.644093  3983 ts_manager.cc:194] Registered new tserver with Master: 18ec33df405d436c96c248fe5ff6950d (127.3.215.65:39593)
I20260812 06:16:53.644286  3933 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012424614s
I20260812 06:16:53.645443  3983 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:58540
I20260812 06:16:53.654243  3983 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:58546:
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:16:53.668782  4158 tablet_service.cc:1511] Processing CreateTablet for tablet 35d56f6ee33c41209334fd0783a56e08 (DEFAULT_TABLE table=heavy-update-compaction-test [id=01b2c9c04b3941d7b9b9e5ad458394d9]), partition=
I20260812 06:16:53.669319  4158 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 35d56f6ee33c41209334fd0783a56e08. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:53.671684  4237 tablet_bootstrap.cc:492] T 35d56f6ee33c41209334fd0783a56e08 P 18ec33df405d436c96c248fe5ff6950d: Bootstrap starting.
I20260812 06:16:53.672971  4237 tablet_bootstrap.cc:654] T 35d56f6ee33c41209334fd0783a56e08 P 18ec33df405d436c96c248fe5ff6950d: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:53.674134  4237 tablet_bootstrap.cc:492] T 35d56f6ee33c41209334fd0783a56e08 P 18ec33df405d436c96c248fe5ff6950d: No bootstrap required, opened a new log
I20260812 06:16:53.674252  4237 ts_tablet_manager.cc:1403] T 35d56f6ee33c41209334fd0783a56e08 P 18ec33df405d436c96c248fe5ff6950d: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:16:53.674703  4237 raft_consensus.cc:359] T 35d56f6ee33c41209334fd0783a56e08 P 18ec33df405d436c96c248fe5ff6950d [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "18ec33df405d436c96c248fe5ff6950d" member_type: VOTER last_known_addr { host: "127.3.215.65" port: 39593 } }
I20260812 06:16:53.674824  4237 raft_consensus.cc:385] T 35d56f6ee33c41209334fd0783a56e08 P 18ec33df405d436c96c248fe5ff6950d [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:53.674872  4237 raft_consensus.cc:740] T 35d56f6ee33c41209334fd0783a56e08 P 18ec33df405d436c96c248fe5ff6950d [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 18ec33df405d436c96c248fe5ff6950d, State: Initialized, Role: FOLLOWER
I20260812 06:16:53.675017  4237 consensus_queue.cc:260] T 35d56f6ee33c41209334fd0783a56e08 P 18ec33df405d436c96c248fe5ff6950d [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: "18ec33df405d436c96c248fe5ff6950d" member_type: VOTER last_known_addr { host: "127.3.215.65" port: 39593 } }
I20260812 06:16:53.675133  4237 raft_consensus.cc:399] T 35d56f6ee33c41209334fd0783a56e08 P 18ec33df405d436c96c248fe5ff6950d [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:53.675184  4237 raft_consensus.cc:493] T 35d56f6ee33c41209334fd0783a56e08 P 18ec33df405d436c96c248fe5ff6950d [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:53.675235  4237 raft_consensus.cc:3060] T 35d56f6ee33c41209334fd0783a56e08 P 18ec33df405d436c96c248fe5ff6950d [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:53.676080  4237 raft_consensus.cc:515] T 35d56f6ee33c41209334fd0783a56e08 P 18ec33df405d436c96c248fe5ff6950d [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "18ec33df405d436c96c248fe5ff6950d" member_type: VOTER last_known_addr { host: "127.3.215.65" port: 39593 } }
I20260812 06:16:53.676237  4237 leader_election.cc:304] T 35d56f6ee33c41209334fd0783a56e08 P 18ec33df405d436c96c248fe5ff6950d [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: 18ec33df405d436c96c248fe5ff6950d; no voters: 
I20260812 06:16:53.676478  4237 leader_election.cc:290] T 35d56f6ee33c41209334fd0783a56e08 P 18ec33df405d436c96c248fe5ff6950d [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:53.676575  4241 raft_consensus.cc:2804] T 35d56f6ee33c41209334fd0783a56e08 P 18ec33df405d436c96c248fe5ff6950d [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:53.676815  4241 raft_consensus.cc:697] T 35d56f6ee33c41209334fd0783a56e08 P 18ec33df405d436c96c248fe5ff6950d [term 1 LEADER]: Becoming Leader. State: Replica: 18ec33df405d436c96c248fe5ff6950d, State: Running, Role: LEADER
I20260812 06:16:53.676995  4237 ts_tablet_manager.cc:1434] T 35d56f6ee33c41209334fd0783a56e08 P 18ec33df405d436c96c248fe5ff6950d: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:16:53.677124  4216 heartbeater.cc:499] Master 127.3.215.126:45015 was elected leader, sending a full tablet report...
I20260812 06:16:53.677006  4241 consensus_queue.cc:237] T 35d56f6ee33c41209334fd0783a56e08 P 18ec33df405d436c96c248fe5ff6950d [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: "18ec33df405d436c96c248fe5ff6950d" member_type: VOTER last_known_addr { host: "127.3.215.65" port: 39593 } }
I20260812 06:16:53.679733  3983 catalog_manager.cc:5719] T 35d56f6ee33c41209334fd0783a56e08 P 18ec33df405d436c96c248fe5ff6950d reported cstate change: term changed from 0 to 1, leader changed from <none> to 18ec33df405d436c96c248fe5ff6950d (127.3.215.65). New cstate: current_term: 1 leader_uuid: "18ec33df405d436c96c248fe5ff6950d" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "18ec33df405d436c96c248fe5ff6950d" member_type: VOTER last_known_addr { host: "127.3.215.65" port: 39593 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:53.745759  3933 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.056s	user 0.017s	sys 0.009s
I20260812 06:16:53.882462  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling FlushMRSOp(35d56f6ee33c41209334fd0783a56e08): perf score=19.054940
I20260812 06:16:54.060528  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: FlushMRSOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.178s	user 0.131s	sys 0.041s Metrics: {"bytes_written":12307490,"cfile_init":1,"compiler_manager_pool.queue_time_us":221,"delete_count":0,"dirs.queue_time_us":63,"dirs.run_cpu_time_us":229,"dirs.run_wall_time_us":910,"drs_written":1,"lbm_read_time_us":72,"lbm_reads_lt_1ms":4,"lbm_write_time_us":45540,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":144,"threads_started":1,"update_count":1500}
I20260812 06:16:54.065496  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08): perf score=2.188937
I20260812 06:16:54.100260  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.033s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":13234,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":102,"reinsert_count":0,"update_count":500}
I20260812 06:16:54.100912  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling LogGCOp(35d56f6ee33c41209334fd0783a56e08): free 20743831 bytes of WAL
I20260812 06:16:54.101325  4117 log_reader.cc:385] T 35d56f6ee33c41209334fd0783a56e08: removed 2 log segments from log reader
I20260812 06:16:54.101467  4117 log.cc:1079] T 35d56f6ee33c41209334fd0783a56e08 P 18ec33df405d436c96c248fe5ff6950d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/35d56f6ee33c41209334fd0783a56e08/wal-000000001 (ops 1-6)
I20260812 06:16:54.101600  4117 log.cc:1079] T 35d56f6ee33c41209334fd0783a56e08 P 18ec33df405d436c96c248fe5ff6950d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/35d56f6ee33c41209334fd0783a56e08/wal-000000002 (ops 7-11)
I20260812 06:16:54.107537  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: LogGCOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.006s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:16:54.108204  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling MajorDeltaCompactionOp(35d56f6ee33c41209334fd0783a56e08): perf score=1.000000
I20260812 06:16:54.295637  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: MajorDeltaCompactionOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.187s	user 0.150s	sys 0.031s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":571,"lbm_read_time_us":12344,"lbm_reads_lt_1ms":464,"lbm_write_time_us":31564,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":317,"threads_started":5,"update_count":2000}
I20260812 06:16:54.296128  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08): perf score=14.095187
I20260812 06:16:54.353886  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.058s	user 0.028s	sys 0.023s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23683,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:54.354329  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08): perf score=2.188937
I20260812 06:16:54.365464  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4075,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:54.365911  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling MajorDeltaCompactionOp(35d56f6ee33c41209334fd0783a56e08): perf score=1.000000
I20260812 06:16:54.518746  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: MajorDeltaCompactionOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.153s	user 0.125s	sys 0.025s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":208,"lbm_read_time_us":12325,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30101,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4608,"update_count":2500}
I20260812 06:16:54.519387  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling UndoDeltaBlockGCOp(35d56f6ee33c41209334fd0783a56e08): 16411395 bytes on disk
I20260812 06:16:54.519942  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: UndoDeltaBlockGCOp(35d56f6ee33c41209334fd0783a56e08) 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:16:54.520577  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08): perf score=10.126437
I20260812 06:16:54.551262  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.031s	user 0.016s	sys 0.012s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":13585,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:54.551787  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08): perf score=2.188937
I20260812 06:16:54.562312  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3927,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:54.562783  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling MajorDeltaCompactionOp(35d56f6ee33c41209334fd0783a56e08): perf score=1.000000
I20260812 06:16:54.696395  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: MajorDeltaCompactionOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.133s	user 0.102s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":285,"lbm_read_time_us":9619,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25918,"lbm_writes_lt_1ms":443,"mutex_wait_us":57,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:16:54.696992  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08): perf score=10.126437
I20260812 06:16:54.748608  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.051s	user 0.015s	sys 0.024s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15421,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:54.749145  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08): perf score=2.188937
I20260812 06:16:54.759476  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4121,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:54.760095  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling MajorDeltaCompactionOp(35d56f6ee33c41209334fd0783a56e08): perf score=1.000000
I20260812 06:16:54.903035  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: MajorDeltaCompactionOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.143s	user 0.106s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":199,"lbm_read_time_us":10017,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23057,"lbm_writes_lt_1ms":443,"mutex_wait_us":28,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12672,"update_count":2000}
I20260812 06:16:54.903717  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08): perf score=10.126437
I20260812 06:16:54.948906  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.045s	user 0.034s	sys 0.007s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":18581,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:54.949364  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling MajorDeltaCompactionOp(35d56f6ee33c41209334fd0783a56e08): perf score=1.000000
I20260812 06:16:55.054982  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: MajorDeltaCompactionOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.105s	user 0.090s	sys 0.015s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569748,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":743,"lbm_read_time_us":6085,"lbm_reads_lt_1ms":363,"lbm_write_time_us":19266,"lbm_writes_lt_1ms":343,"mutex_wait_us":453,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":42368,"update_count":1500}
I20260812 06:16:55.055685  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08): perf score=10.126437
I20260812 06:16:55.094830  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.039s	user 0.028s	sys 0.009s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":17476,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:16:55.095350  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08): perf score=2.188937
I20260812 06:16:55.106822  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.011s	user 0.004s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4048,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:55.107398  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling MajorDeltaCompactionOp(35d56f6ee33c41209334fd0783a56e08): perf score=1.000000
I20260812 06:16:55.233301  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: MajorDeltaCompactionOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.126s	user 0.090s	sys 0.035s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":255,"lbm_read_time_us":10013,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23907,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:16:55.233826  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08): perf score=10.126437
I20260812 06:16:55.288753  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.055s	user 0.018s	sys 0.024s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16991,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":1500}
I20260812 06:16:55.289324  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08): perf score=2.188937
I20260812 06:16:55.299950  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.010s	user 0.008s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4098,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:55.300434  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling FlushMRSOp(35d56f6ee33c41209334fd0783a56e08): perf score=1.000000
I20260812 06:16:55.346669  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: FlushMRSOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.046s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":61,"dirs.run_cpu_time_us":281,"dirs.run_wall_time_us":1584,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2084,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:16:55.347574  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling LogGCOp(35d56f6ee33c41209334fd0783a56e08): free 108535498 bytes of WAL
I20260812 06:16:55.347787  4117 log_reader.cc:385] T 35d56f6ee33c41209334fd0783a56e08: removed 11 log segments from log reader
I20260812 06:16:55.347836  4117 log.cc:1079] T 35d56f6ee33c41209334fd0783a56e08 P 18ec33df405d436c96c248fe5ff6950d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/35d56f6ee33c41209334fd0783a56e08/wal-000000003 (ops 12-16)
I20260812 06:16:55.347870  4117 log.cc:1079] T 35d56f6ee33c41209334fd0783a56e08 P 18ec33df405d436c96c248fe5ff6950d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/35d56f6ee33c41209334fd0783a56e08/wal-000000004 (ops 17-20)
I20260812 06:16:55.347905  4117 log.cc:1079] T 35d56f6ee33c41209334fd0783a56e08 P 18ec33df405d436c96c248fe5ff6950d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/35d56f6ee33c41209334fd0783a56e08/wal-000000005 (ops 21-25)
I20260812 06:16:55.347941  4117 log.cc:1079] T 35d56f6ee33c41209334fd0783a56e08 P 18ec33df405d436c96c248fe5ff6950d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/35d56f6ee33c41209334fd0783a56e08/wal-000000006 (ops 26-30)
I20260812 06:16:55.347966  4117 log.cc:1079] T 35d56f6ee33c41209334fd0783a56e08 P 18ec33df405d436c96c248fe5ff6950d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/35d56f6ee33c41209334fd0783a56e08/wal-000000007 (ops 31-35)
I20260812 06:16:55.347994  4117 log.cc:1079] T 35d56f6ee33c41209334fd0783a56e08 P 18ec33df405d436c96c248fe5ff6950d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/35d56f6ee33c41209334fd0783a56e08/wal-000000008 (ops 36-40)
I20260812 06:16:55.348022  4117 log.cc:1079] T 35d56f6ee33c41209334fd0783a56e08 P 18ec33df405d436c96c248fe5ff6950d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/35d56f6ee33c41209334fd0783a56e08/wal-000000009 (ops 41-44)
I20260812 06:16:55.348050  4117 log.cc:1079] T 35d56f6ee33c41209334fd0783a56e08 P 18ec33df405d436c96c248fe5ff6950d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/35d56f6ee33c41209334fd0783a56e08/wal-000000010 (ops 45-49)
I20260812 06:16:55.348083  4117 log.cc:1079] T 35d56f6ee33c41209334fd0783a56e08 P 18ec33df405d436c96c248fe5ff6950d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/35d56f6ee33c41209334fd0783a56e08/wal-000000011 (ops 50-54)
I20260812 06:16:55.348116  4117 log.cc:1079] T 35d56f6ee33c41209334fd0783a56e08 P 18ec33df405d436c96c248fe5ff6950d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/35d56f6ee33c41209334fd0783a56e08/wal-000000012 (ops 55-59)
I20260812 06:16:55.348146  4117 log.cc:1079] T 35d56f6ee33c41209334fd0783a56e08 P 18ec33df405d436c96c248fe5ff6950d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/35d56f6ee33c41209334fd0783a56e08/wal-000000013 (ops 60-64)
I20260812 06:16:55.379823  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: LogGCOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.032s	user 0.004s	sys 0.023s Metrics: {}
I20260812 06:16:55.380306  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling UndoDeltaBlockGCOp(35d56f6ee33c41209334fd0783a56e08): 447 bytes on disk
I20260812 06:16:55.380827  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: UndoDeltaBlockGCOp(35d56f6ee33c41209334fd0783a56e08) 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:16:55.381393  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08): perf score=2.188937
I20260812 06:16:55.410173  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.029s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5270,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:55.410651  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08): perf score=2.188937
I20260812 06:16:55.422197  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.011s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4555,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:55.422665  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling MajorDeltaCompactionOp(35d56f6ee33c41209334fd0783a56e08): perf score=1.000000
I20260812 06:16:55.611579  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: MajorDeltaCompactionOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.189s	user 0.120s	sys 0.067s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877339,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":560,"lbm_read_time_us":15044,"lbm_reads_lt_1ms":674,"lbm_write_time_us":31288,"lbm_writes_lt_1ms":643,"mutex_wait_us":91,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2432,"thread_start_us":78,"threads_started":1,"update_count":3000}
I20260812 06:16:55.612212  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08): perf score=14.095187
I20260812 06:16:55.656003  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.044s	user 0.016s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20063,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:55.656457  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling MajorDeltaCompactionOp(35d56f6ee33c41209334fd0783a56e08): perf score=1.000000
I20260812 06:16:55.803332  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: MajorDeltaCompactionOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.147s	user 0.101s	sys 0.039s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672157,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":145,"lbm_read_time_us":11829,"lbm_reads_lt_1ms":467,"lbm_write_time_us":22846,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:16:55.804044  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08): perf score=11.118625
I20260812 06:16:55.839485  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.035s	user 0.025s	sys 0.008s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14928,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:55.840171  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08): perf score=2.188937
I20260812 06:16:55.857806  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.017s	user 0.007s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6219,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:55.858325  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling MajorDeltaCompactionOp(35d56f6ee33c41209334fd0783a56e08): perf score=1.000000
I20260812 06:16:55.988665  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: MajorDeltaCompactionOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.130s	user 0.092s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":2570,"lbm_read_time_us":8402,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25891,"lbm_writes_lt_1ms":443,"mutex_wait_us":109,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:16:55.989306  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08): perf score=10.126437
I20260812 06:16:56.031409  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.042s	user 0.028s	sys 0.012s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":18369,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:56.031914  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08): perf score=2.188937
I20260812 06:16:56.050647  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.019s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5312,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:56.051167  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling MajorDeltaCompactionOp(35d56f6ee33c41209334fd0783a56e08): perf score=1.000000
I20260812 06:16:56.182830  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: MajorDeltaCompactionOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.132s	user 0.105s	sys 0.026s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1032,"lbm_read_time_us":9276,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25823,"lbm_writes_lt_1ms":443,"mutex_wait_us":345,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:16:56.183386  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08): perf score=11.118625
I20260812 06:16:56.214334  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.031s	user 0.012s	sys 0.017s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":13535,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:56.214775  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08): perf score=2.188937
I20260812 06:16:56.226946  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4638,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:56.227383  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling MajorDeltaCompactionOp(35d56f6ee33c41209334fd0783a56e08): perf score=1.000000
I20260812 06:16:56.363534  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: MajorDeltaCompactionOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.136s	user 0.088s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":183,"lbm_read_time_us":10286,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26793,"lbm_writes_lt_1ms":443,"mutex_wait_us":32,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11776,"update_count":2000}
I20260812 06:16:56.364109  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08): perf score=10.126437
I20260812 06:16:56.416237  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.052s	user 0.032s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15260,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:56.416755  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08): perf score=2.188937
I20260812 06:16:56.427132  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4061,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:56.427554  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling MajorDeltaCompactionOp(35d56f6ee33c41209334fd0783a56e08): perf score=1.000000
I20260812 06:16:56.575781  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: MajorDeltaCompactionOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.148s	user 0.100s	sys 0.044s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":228,"lbm_read_time_us":11018,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24556,"lbm_writes_lt_1ms":443,"mutex_wait_us":37,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:16:56.576349  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08): perf score=10.126437
I20260812 06:16:56.614480  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.038s	user 0.019s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13783,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:56.615046  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling MajorDeltaCompactionOp(35d56f6ee33c41209334fd0783a56e08): perf score=1.000000
I20260812 06:16:56.716655  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: MajorDeltaCompactionOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.101s	user 0.077s	sys 0.024s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569746,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":382,"lbm_read_time_us":6125,"lbm_reads_lt_1ms":363,"lbm_write_time_us":18783,"lbm_writes_lt_1ms":343,"mutex_wait_us":47,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":6528,"update_count":1500}
I20260812 06:16:56.717377  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08): perf score=10.126437
I20260812 06:16:56.758100  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.041s	user 0.011s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15714,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:56.758613  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08): perf score=2.188937
I20260812 06:16:56.768934  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.010s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3921,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:56.769516  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling FlushMRSOp(35d56f6ee33c41209334fd0783a56e08): perf score=1.000000
I20260812 06:16:56.804549  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: FlushMRSOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.035s	user 0.029s	sys 0.004s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":66,"dirs.run_cpu_time_us":183,"dirs.run_wall_time_us":1448,"drs_written":1,"lbm_read_time_us":41,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1629,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:16:56.805284  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling LogGCOp(35d56f6ee33c41209334fd0783a56e08): free 124257243 bytes of WAL
I20260812 06:16:56.805517  4117 log_reader.cc:385] T 35d56f6ee33c41209334fd0783a56e08: removed 12 log segments from log reader
I20260812 06:16:56.805562  4117 log.cc:1079] T 35d56f6ee33c41209334fd0783a56e08 P 18ec33df405d436c96c248fe5ff6950d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/35d56f6ee33c41209334fd0783a56e08/wal-000000014 (ops 65-69)
I20260812 06:16:56.805591  4117 log.cc:1079] T 35d56f6ee33c41209334fd0783a56e08 P 18ec33df405d436c96c248fe5ff6950d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/35d56f6ee33c41209334fd0783a56e08/wal-000000015 (ops 70-74)
I20260812 06:16:56.805655  4117 log.cc:1079] T 35d56f6ee33c41209334fd0783a56e08 P 18ec33df405d436c96c248fe5ff6950d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/35d56f6ee33c41209334fd0783a56e08/wal-000000016 (ops 75-79)
I20260812 06:16:56.805685  4117 log.cc:1079] T 35d56f6ee33c41209334fd0783a56e08 P 18ec33df405d436c96c248fe5ff6950d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/35d56f6ee33c41209334fd0783a56e08/wal-000000017 (ops 80-84)
I20260812 06:16:56.805722  4117 log.cc:1079] T 35d56f6ee33c41209334fd0783a56e08 P 18ec33df405d436c96c248fe5ff6950d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/35d56f6ee33c41209334fd0783a56e08/wal-000000018 (ops 85-89)
I20260812 06:16:56.805747  4117 log.cc:1079] T 35d56f6ee33c41209334fd0783a56e08 P 18ec33df405d436c96c248fe5ff6950d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/35d56f6ee33c41209334fd0783a56e08/wal-000000019 (ops 90-94)
I20260812 06:16:56.805783  4117 log.cc:1079] T 35d56f6ee33c41209334fd0783a56e08 P 18ec33df405d436c96c248fe5ff6950d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/35d56f6ee33c41209334fd0783a56e08/wal-000000020 (ops 95-98)
I20260812 06:16:56.805824  4117 log.cc:1079] T 35d56f6ee33c41209334fd0783a56e08 P 18ec33df405d436c96c248fe5ff6950d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/35d56f6ee33c41209334fd0783a56e08/wal-000000021 (ops 99-103)
I20260812 06:16:56.805862  4117 log.cc:1079] T 35d56f6ee33c41209334fd0783a56e08 P 18ec33df405d436c96c248fe5ff6950d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/35d56f6ee33c41209334fd0783a56e08/wal-000000022 (ops 104-108)
I20260812 06:16:56.805900  4117 log.cc:1079] T 35d56f6ee33c41209334fd0783a56e08 P 18ec33df405d436c96c248fe5ff6950d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/35d56f6ee33c41209334fd0783a56e08/wal-000000023 (ops 109-113)
I20260812 06:16:56.805924  4117 log.cc:1079] T 35d56f6ee33c41209334fd0783a56e08 P 18ec33df405d436c96c248fe5ff6950d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/35d56f6ee33c41209334fd0783a56e08/wal-000000024 (ops 114-118)
I20260812 06:16:56.805953  4117 log.cc:1079] T 35d56f6ee33c41209334fd0783a56e08 P 18ec33df405d436c96c248fe5ff6950d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/35d56f6ee33c41209334fd0783a56e08/wal-000000025 (ops 119-123)
I20260812 06:16:56.833431  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: LogGCOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.028s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:16:56.833827  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling UndoDeltaBlockGCOp(35d56f6ee33c41209334fd0783a56e08): 462 bytes on disk
I20260812 06:16:56.834245  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: UndoDeltaBlockGCOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4}
I20260812 06:16:56.834744  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08): perf score=6.157687
I20260812 06:16:56.859112  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.024s	user 0.012s	sys 0.010s Metrics: {"bytes_written":7384593,"delete_count":0,"lbm_write_time_us":9812,"lbm_writes_lt_1ms":183,"reinsert_count":0,"update_count":900}
I20260812 06:16:56.859616  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling MajorDeltaCompactionOp(35d56f6ee33c41209334fd0783a56e08): perf score=1.000000
I20260812 06:16:57.036547  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: MajorDeltaCompactionOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.177s	user 0.118s	sys 0.049s Metrics: {"cfile_cache_miss":613,"cfile_cache_miss_bytes":28056736,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":792,"lbm_read_time_us":11287,"lbm_reads_lt_1ms":649,"lbm_write_time_us":35999,"lbm_writes_lt_1ms":623,"mutex_wait_us":307,"peak_mem_usage":72641004,"reinsert_count":0,"spinlock_wait_cycles":9856,"thread_start_us":79,"threads_started":1,"update_count":2900}
I20260812 06:16:57.037403  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08): perf score=15.087375
I20260812 06:16:57.091652  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.054s	user 0.031s	sys 0.015s Metrics: {"bytes_written":17230394,"delete_count":0,"lbm_write_time_us":21677,"lbm_writes_lt_1ms":423,"reinsert_count":0,"update_count":2100}
I20260812 06:16:57.092115  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08): perf score=2.188937
I20260812 06:16:57.104283  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4209,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:57.105108  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling MajorDeltaCompactionOp(35d56f6ee33c41209334fd0783a56e08): perf score=1.000000
I20260812 06:16:57.251096  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: MajorDeltaCompactionOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.146s	user 0.106s	sys 0.035s Metrics: {"cfile_cache_miss":552,"cfile_cache_miss_bytes":25595181,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":307,"lbm_read_time_us":11493,"lbm_reads_lt_1ms":592,"lbm_write_time_us":28510,"lbm_writes_lt_1ms":563,"mutex_wait_us":71,"peak_mem_usage":64976984,"reinsert_count":0,"spinlock_wait_cycles":6272,"update_count":2600}
I20260812 06:16:57.251754  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08): perf score=14.095187
I20260812 06:16:57.308319  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.056s	user 0.027s	sys 0.021s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23340,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:57.308858  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08): perf score=2.188937
I20260812 06:16:57.319594  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.011s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4028,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:57.320195  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling MajorDeltaCompactionOp(35d56f6ee33c41209334fd0783a56e08): perf score=1.000000
I20260812 06:16:57.473834  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: MajorDeltaCompactionOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.153s	user 0.112s	sys 0.041s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":208,"lbm_read_time_us":11283,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29182,"lbm_writes_lt_1ms":543,"mutex_wait_us":55,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:16:57.474637  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08): perf score=12.110812
I20260812 06:16:57.516377  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.042s	user 0.032s	sys 0.006s Metrics: {"bytes_written":13538208,"delete_count":0,"lbm_write_time_us":18222,"lbm_writes_lt_1ms":333,"reinsert_count":0,"update_count":1650}
I20260812 06:16:57.516920  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08): perf score=1.196750
I20260812 06:16:57.526655  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":2871905,"delete_count":0,"lbm_write_time_us":3540,"lbm_writes_lt_1ms":73,"reinsert_count":0,"update_count":350}
I20260812 06:16:57.527104  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling MajorDeltaCompactionOp(35d56f6ee33c41209334fd0783a56e08): perf score=1.000000
I20260812 06:16:57.674490  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: MajorDeltaCompactionOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.147s	user 0.091s	sys 0.051s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672241,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":266,"lbm_read_time_us":10533,"lbm_reads_lt_1ms":468,"lbm_write_time_us":25465,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:16:57.675274  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08): perf score=11.118625
I20260812 06:16:57.705969  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.031s	user 0.014s	sys 0.015s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":13266,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:57.706581  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08): perf score=2.188937
I20260812 06:16:57.725112  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.018s	user 0.011s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6129,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:57.725673  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling MajorDeltaCompactionOp(35d56f6ee33c41209334fd0783a56e08): perf score=1.000000
I20260812 06:16:57.871753  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: MajorDeltaCompactionOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.146s	user 0.114s	sys 0.025s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":977,"lbm_read_time_us":8733,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26274,"lbm_writes_lt_1ms":443,"mutex_wait_us":386,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:16:57.872453  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08): perf score=11.118625
I20260812 06:16:57.919812  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.047s	user 0.012s	sys 0.028s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":19369,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:57.920306  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08): perf score=2.188937
I20260812 06:16:57.932392  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3909,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:57.933039  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08): perf score=2.188937
I20260812 06:16:57.942687  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3584,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:57.943231  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling MajorDeltaCompactionOp(35d56f6ee33c41209334fd0783a56e08): perf score=1.000000
I20260812 06:16:58.088183  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: MajorDeltaCompactionOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.145s	user 0.114s	sys 0.027s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774798,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":682,"lbm_read_time_us":11191,"lbm_reads_lt_1ms":573,"lbm_write_time_us":28754,"lbm_writes_lt_1ms":543,"mutex_wait_us":35,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9728,"update_count":2500}
I20260812 06:16:58.089534  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08): perf score=11.118625
I20260812 06:16:58.125617  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.036s	user 0.021s	sys 0.012s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":14351,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:58.126241  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08): perf score=2.188937
I20260812 06:16:58.149250  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.023s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3938559,"delete_count":0,"lbm_write_time_us":5382,"lbm_writes_lt_1ms":99,"reinsert_count":0,"update_count":480}
I20260812 06:16:58.149776  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08): perf score=2.188937
I20260812 06:16:58.160285  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.010s	user 0.006s	sys 0.003s Metrics: {"bytes_written":3856509,"delete_count":0,"lbm_write_time_us":4071,"lbm_writes_lt_1ms":97,"reinsert_count":0,"update_count":470}
I20260812 06:16:58.160758  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling FlushMRSOp(35d56f6ee33c41209334fd0783a56e08): perf score=1.000000
I20260812 06:16:58.196938  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: FlushMRSOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.036s	user 0.033s	sys 0.001s Metrics: {"bytes_written":1234475,"cfile_init":1,"dirs.queue_time_us":67,"dirs.run_cpu_time_us":237,"dirs.run_wall_time_us":1376,"drs_written":1,"lbm_read_time_us":86,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2374,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:16:58.197727  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling LogGCOp(35d56f6ee33c41209334fd0783a56e08): free 120553630 bytes of WAL
I20260812 06:16:58.198153  4117 log_reader.cc:385] T 35d56f6ee33c41209334fd0783a56e08: removed 12 log segments from log reader
I20260812 06:16:58.198228  4117 log.cc:1079] T 35d56f6ee33c41209334fd0783a56e08 P 18ec33df405d436c96c248fe5ff6950d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/35d56f6ee33c41209334fd0783a56e08/wal-000000026 (ops 124-128)
I20260812 06:16:58.198268  4117 log.cc:1079] T 35d56f6ee33c41209334fd0783a56e08 P 18ec33df405d436c96c248fe5ff6950d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/35d56f6ee33c41209334fd0783a56e08/wal-000000027 (ops 129-133)
I20260812 06:16:58.198292  4117 log.cc:1079] T 35d56f6ee33c41209334fd0783a56e08 P 18ec33df405d436c96c248fe5ff6950d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/35d56f6ee33c41209334fd0783a56e08/wal-000000028 (ops 134-138)
I20260812 06:16:58.198318  4117 log.cc:1079] T 35d56f6ee33c41209334fd0783a56e08 P 18ec33df405d436c96c248fe5ff6950d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/35d56f6ee33c41209334fd0783a56e08/wal-000000029 (ops 139-143)
I20260812 06:16:58.198344  4117 log.cc:1079] T 35d56f6ee33c41209334fd0783a56e08 P 18ec33df405d436c96c248fe5ff6950d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/35d56f6ee33c41209334fd0783a56e08/wal-000000030 (ops 144-148)
I20260812 06:16:58.198369  4117 log.cc:1079] T 35d56f6ee33c41209334fd0783a56e08 P 18ec33df405d436c96c248fe5ff6950d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/35d56f6ee33c41209334fd0783a56e08/wal-000000031 (ops 149-152)
I20260812 06:16:58.198400  4117 log.cc:1079] T 35d56f6ee33c41209334fd0783a56e08 P 18ec33df405d436c96c248fe5ff6950d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/35d56f6ee33c41209334fd0783a56e08/wal-000000032 (ops 153-157)
I20260812 06:16:58.198423  4117 log.cc:1079] T 35d56f6ee33c41209334fd0783a56e08 P 18ec33df405d436c96c248fe5ff6950d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/35d56f6ee33c41209334fd0783a56e08/wal-000000033 (ops 158-162)
I20260812 06:16:58.198444  4117 log.cc:1079] T 35d56f6ee33c41209334fd0783a56e08 P 18ec33df405d436c96c248fe5ff6950d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/35d56f6ee33c41209334fd0783a56e08/wal-000000034 (ops 163-166)
I20260812 06:16:58.198472  4117 log.cc:1079] T 35d56f6ee33c41209334fd0783a56e08 P 18ec33df405d436c96c248fe5ff6950d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/35d56f6ee33c41209334fd0783a56e08/wal-000000035 (ops 167-171)
I20260812 06:16:58.198498  4117 log.cc:1079] T 35d56f6ee33c41209334fd0783a56e08 P 18ec33df405d436c96c248fe5ff6950d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/35d56f6ee33c41209334fd0783a56e08/wal-000000036 (ops 172-176)
I20260812 06:16:58.198531  4117 log.cc:1079] T 35d56f6ee33c41209334fd0783a56e08 P 18ec33df405d436c96c248fe5ff6950d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/35d56f6ee33c41209334fd0783a56e08/wal-000000037 (ops 177-181)
I20260812 06:16:58.230931  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: LogGCOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.033s	user 0.001s	sys 0.032s Metrics: {}
I20260812 06:16:58.231457  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling UndoDeltaBlockGCOp(35d56f6ee33c41209334fd0783a56e08): 473 bytes on disk
I20260812 06:16:58.232261  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: UndoDeltaBlockGCOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":121,"lbm_reads_lt_1ms":4}
I20260812 06:16:58.232959  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08): perf score=2.188937
I20260812 06:16:58.254258  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.021s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4437,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:58.254866  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling LogGCOp(35d56f6ee33c41209334fd0783a56e08): free 12017961 bytes of WAL
I20260812 06:16:58.255682  4117 log_reader.cc:385] T 35d56f6ee33c41209334fd0783a56e08: removed 1 log segments from log reader
I20260812 06:16:58.255743  4117 log.cc:1079] T 35d56f6ee33c41209334fd0783a56e08 P 18ec33df405d436c96c248fe5ff6950d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/35d56f6ee33c41209334fd0783a56e08/wal-000000038 (ops 182-186)
I20260812 06:16:58.258936  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: LogGCOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:16:58.259301  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08): perf score=2.188937
I20260812 06:16:58.271018  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4108,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:58.271688  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling MajorDeltaCompactionOp(35d56f6ee33c41209334fd0783a56e08): perf score=1.000000
I20260812 06:16:58.458384  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: MajorDeltaCompactionOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.186s	user 0.160s	sys 0.026s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979865,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":302,"lbm_read_time_us":13941,"lbm_reads_lt_1ms":775,"lbm_write_time_us":38280,"lbm_writes_lt_1ms":743,"mutex_wait_us":21,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":10496,"thread_start_us":72,"threads_started":1,"update_count":3500}
I20260812 06:16:58.461025  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08): perf score=14.095187
I20260812 06:16:58.512385  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.051s	user 0.038s	sys 0.010s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22753,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:58.513127  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08): perf score=2.188937
I20260812 06:16:58.540763  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.027s	user 0.002s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5930,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:58.541266  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08): perf score=2.188937
I20260812 06:16:58.551708  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: FlushDeltaMemStoresOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.010s	user 0.003s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4063,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:58.552218  4218 maintenance_manager.cc:419] P 18ec33df405d436c96c248fe5ff6950d: Scheduling MajorDeltaCompactionOp(35d56f6ee33c41209334fd0783a56e08): perf score=1.000000
I20260812 06:16:58.587874  3933 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.842s	user 1.779s	sys 0.147s
I20260812 06:16:58.648375  3933 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.060s	user 0.002s	sys 0.000s
I20260812 06:16:58.649058  3933 tablet_server.cc:179] TabletServer@127.3.215.65:0 shutting down...
I20260812 06:16:58.708822  4117 maintenance_manager.cc:643] P 18ec33df405d436c96c248fe5ff6950d: MajorDeltaCompactionOp(35d56f6ee33c41209334fd0783a56e08) complete. Timing: real 0.156s	user 0.121s	sys 0.035s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877220,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":528,"lbm_read_time_us":13861,"lbm_reads_lt_1ms":669,"lbm_write_time_us":29341,"lbm_writes_lt_1ms":643,"mutex_wait_us":41,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":25472,"update_count":3000}
I20260812 06:16:58.709672  3933 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:16:58.710103  3933 tablet_replica.cc:333] T 35d56f6ee33c41209334fd0783a56e08 P 18ec33df405d436c96c248fe5ff6950d: stopping tablet replica
I20260812 06:16:58.710356  3933 raft_consensus.cc:2243] T 35d56f6ee33c41209334fd0783a56e08 P 18ec33df405d436c96c248fe5ff6950d [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:58.710618  3933 raft_consensus.cc:2272] T 35d56f6ee33c41209334fd0783a56e08 P 18ec33df405d436c96c248fe5ff6950d [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:58.729563  3933 tablet_server.cc:196] TabletServer@127.3.215.65:0 shutdown complete.
I20260812 06:16:58.762167  3933 master.cc:562] Master@127.3.215.126:45015 shutting down...
I20260812 06:16:58.766266  3933 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 0d9dcc994fdb4835aba90ad24fd0a468 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:58.766487  3933 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 0d9dcc994fdb4835aba90ad24fd0a468 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:58.766589  3933 tablet_replica.cc:333] T 00000000000000000000000000000000 P 0d9dcc994fdb4835aba90ad24fd0a468: stopping tablet replica
I20260812 06:16:58.778978  3933 master.cc:584] Master@127.3.215.126:45015 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5431 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:16:58.874446  3933 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.3.215.126:43287
I20260812 06:16:58.874871  3933 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:58.877024  4287 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:16:58.877179  4290 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:16:58.877198  3933 server_base.cc:1061] running on GCE node
W20260812 06:16:58.877460  4286 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:16:58.877686  3933 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:58.877727  3933 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:16:58.877741  3933 hybrid_clock.cc:648] HybridClock initialized: now 1786515418877741 us; error 0 us; skew 500 ppm
I20260812 06:16:58.878631  3933 webserver.cc:533] Webserver started at http://127.3.215.126:40133/ using document root <none> and password file <none>
I20260812 06:16:58.878770  3933 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:58.878819  3933 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:58.878887  3933 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:58.879238  3933 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413432700-3933-0/minicluster-data/master-0-root/instance:
uuid: "29853d923a6846cc943a7a246c669d3c"
format_stamp: "Formatted at 2026-08-12 06:16:58 on dist-test-slave-2kcd"
I20260812 06:16:58.880674  3933 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:16:58.881699  4300 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:16:58.881974  3933 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:58.882040  3933 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413432700-3933-0/minicluster-data/master-0-root
uuid: "29853d923a6846cc943a7a246c669d3c"
format_stamp: "Formatted at 2026-08-12 06:16:58 on dist-test-slave-2kcd"
I20260812 06:16:58.882095  3933 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413432700-3933-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413432700-3933-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413432700-3933-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:16:58.890533  3933 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:58.890889  3933 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:58.895151  3933 rpc_server.cc:307] RPC server started. Bound to: 127.3.215.126:43287
I20260812 06:16:58.900023  4381 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.3.215.126:43287 every 8 connection(s)
I20260812 06:16:58.903623  4382 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:16:58.909468  4382 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 29853d923a6846cc943a7a246c669d3c: Bootstrap starting.
I20260812 06:16:58.910223  4382 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 29853d923a6846cc943a7a246c669d3c: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:58.911212  4382 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 29853d923a6846cc943a7a246c669d3c: No bootstrap required, opened a new log
I20260812 06:16:58.911566  4382 raft_consensus.cc:359] T 00000000000000000000000000000000 P 29853d923a6846cc943a7a246c669d3c [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "29853d923a6846cc943a7a246c669d3c" member_type: VOTER }
I20260812 06:16:58.911648  4382 raft_consensus.cc:385] T 00000000000000000000000000000000 P 29853d923a6846cc943a7a246c669d3c [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:58.911670  4382 raft_consensus.cc:740] T 00000000000000000000000000000000 P 29853d923a6846cc943a7a246c669d3c [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 29853d923a6846cc943a7a246c669d3c, State: Initialized, Role: FOLLOWER
I20260812 06:16:58.911773  4382 consensus_queue.cc:260] T 00000000000000000000000000000000 P 29853d923a6846cc943a7a246c669d3c [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: "29853d923a6846cc943a7a246c669d3c" member_type: VOTER }
I20260812 06:16:58.911835  4382 raft_consensus.cc:399] T 00000000000000000000000000000000 P 29853d923a6846cc943a7a246c669d3c [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:58.911859  4382 raft_consensus.cc:493] T 00000000000000000000000000000000 P 29853d923a6846cc943a7a246c669d3c [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:58.911893  4382 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 29853d923a6846cc943a7a246c669d3c [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:58.912489  4382 raft_consensus.cc:515] T 00000000000000000000000000000000 P 29853d923a6846cc943a7a246c669d3c [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "29853d923a6846cc943a7a246c669d3c" member_type: VOTER }
I20260812 06:16:58.912601  4382 leader_election.cc:304] T 00000000000000000000000000000000 P 29853d923a6846cc943a7a246c669d3c [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: 29853d923a6846cc943a7a246c669d3c; no voters: 
I20260812 06:16:58.912747  4382 leader_election.cc:290] T 00000000000000000000000000000000 P 29853d923a6846cc943a7a246c669d3c [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:58.912899  4387 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 29853d923a6846cc943a7a246c669d3c [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:58.913116  4387 raft_consensus.cc:697] T 00000000000000000000000000000000 P 29853d923a6846cc943a7a246c669d3c [term 1 LEADER]: Becoming Leader. State: Replica: 29853d923a6846cc943a7a246c669d3c, State: Running, Role: LEADER
I20260812 06:16:58.913323  4387 consensus_queue.cc:237] T 00000000000000000000000000000000 P 29853d923a6846cc943a7a246c669d3c [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: "29853d923a6846cc943a7a246c669d3c" member_type: VOTER }
I20260812 06:16:58.913331  4382 sys_catalog.cc:565] T 00000000000000000000000000000000 P 29853d923a6846cc943a7a246c669d3c [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:58.913837  4388 sys_catalog.cc:455] T 00000000000000000000000000000000 P 29853d923a6846cc943a7a246c669d3c [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "29853d923a6846cc943a7a246c669d3c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "29853d923a6846cc943a7a246c669d3c" member_type: VOTER } }
I20260812 06:16:58.913883  4389 sys_catalog.cc:455] T 00000000000000000000000000000000 P 29853d923a6846cc943a7a246c669d3c [sys.catalog]: SysCatalogTable state changed. Reason: New leader 29853d923a6846cc943a7a246c669d3c. Latest consensus state: current_term: 1 leader_uuid: "29853d923a6846cc943a7a246c669d3c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "29853d923a6846cc943a7a246c669d3c" member_type: VOTER } }
I20260812 06:16:58.913998  4388 sys_catalog.cc:458] T 00000000000000000000000000000000 P 29853d923a6846cc943a7a246c669d3c [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:58.914072  4389 sys_catalog.cc:458] T 00000000000000000000000000000000 P 29853d923a6846cc943a7a246c669d3c [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:58.914516  4398 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:58.915441  4398 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:58.915645  3933 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:58.917286  4398 catalog_manager.cc:1383] Generated new cluster ID: 9f4a78ff08f74cf1a0e546c494782ffd
I20260812 06:16:58.917354  4398 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:58.925259  4398 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:58.925781  4398 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:58.932006  4398 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 29853d923a6846cc943a7a246c669d3c: Generated new TSK 0
I20260812 06:16:58.932179  4398 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:58.948134  3933 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:58.950264  4419 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:16:58.950337  4416 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:16:58.950520  3933 server_base.cc:1061] running on GCE node
W20260812 06:16:58.950322  4421 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:16:58.950780  3933 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:58.950843  3933 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:16:58.950867  3933 hybrid_clock.cc:648] HybridClock initialized: now 1786515418950867 us; error 0 us; skew 500 ppm
I20260812 06:16:58.951740  3933 webserver.cc:533] Webserver started at http://127.3.215.65:38057/ using document root <none> and password file <none>
I20260812 06:16:58.951942  3933 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:58.952018  3933 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:58.952103  3933 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:58.952502  3933 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413432700-3933-0/minicluster-data/ts-0-root/instance:
uuid: "a4262374090e4d0f870b4e85c77c179d"
format_stamp: "Formatted at 2026-08-12 06:16:58 on dist-test-slave-2kcd"
I20260812 06:16:58.954149  3933 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:16:58.955157  4427 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:16:58.955412  3933 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:58.955502  3933 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413432700-3933-0/minicluster-data/ts-0-root
uuid: "a4262374090e4d0f870b4e85c77c179d"
format_stamp: "Formatted at 2026-08-12 06:16:58 on dist-test-slave-2kcd"
I20260812 06:16:58.955571  3933 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413432700-3933-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413432700-3933-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413432700-3933-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:16:58.964744  3933 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:58.965191  3933 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:58.965543  3933 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:58.966161  3933 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:58.966212  3933 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:58.966254  3933 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:58.966279  3933 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:58.972164  3933 rpc_server.cc:307] RPC server started. Bound to: 127.3.215.65:44491
I20260812 06:16:58.972536  4549 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.3.215.65:44491 every 8 connection(s)
I20260812 06:16:58.980252  4550 heartbeater.cc:344] Connected to a master server at 127.3.215.126:43287
I20260812 06:16:58.980366  4550 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:58.980590  4550 heartbeater.cc:507] Master 127.3.215.126:43287 requested a full tablet report, sending...
I20260812 06:16:58.981247  4327 ts_manager.cc:194] Registered new tserver with Master: a4262374090e4d0f870b4e85c77c179d (127.3.215.65:44491)
I20260812 06:16:58.981573  3933 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.008873777s
I20260812 06:16:58.982287  4327 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:54680
I20260812 06:16:58.988618  4327 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:54684:
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:16:58.997136  4487 tablet_service.cc:1511] Processing CreateTablet for tablet 1f1ab76e847f49018cd3a80a3a13690f (DEFAULT_TABLE table=heavy-update-compaction-test [id=20570a92ae5d46e38736e6334187a711]), partition=
I20260812 06:16:58.997390  4487 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 1f1ab76e847f49018cd3a80a3a13690f. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:58.999480  4570 tablet_bootstrap.cc:492] T 1f1ab76e847f49018cd3a80a3a13690f P a4262374090e4d0f870b4e85c77c179d: Bootstrap starting.
I20260812 06:16:59.000907  4570 tablet_bootstrap.cc:654] T 1f1ab76e847f49018cd3a80a3a13690f P a4262374090e4d0f870b4e85c77c179d: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:59.001989  4570 tablet_bootstrap.cc:492] T 1f1ab76e847f49018cd3a80a3a13690f P a4262374090e4d0f870b4e85c77c179d: No bootstrap required, opened a new log
I20260812 06:16:59.002079  4570 ts_tablet_manager.cc:1403] T 1f1ab76e847f49018cd3a80a3a13690f P a4262374090e4d0f870b4e85c77c179d: Time spent bootstrapping tablet: real 0.003s	user 0.000s	sys 0.002s
I20260812 06:16:59.002506  4570 raft_consensus.cc:359] T 1f1ab76e847f49018cd3a80a3a13690f P a4262374090e4d0f870b4e85c77c179d [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a4262374090e4d0f870b4e85c77c179d" member_type: VOTER last_known_addr { host: "127.3.215.65" port: 44491 } }
I20260812 06:16:59.002593  4570 raft_consensus.cc:385] T 1f1ab76e847f49018cd3a80a3a13690f P a4262374090e4d0f870b4e85c77c179d [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:59.002616  4570 raft_consensus.cc:740] T 1f1ab76e847f49018cd3a80a3a13690f P a4262374090e4d0f870b4e85c77c179d [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: a4262374090e4d0f870b4e85c77c179d, State: Initialized, Role: FOLLOWER
I20260812 06:16:59.002776  4570 consensus_queue.cc:260] T 1f1ab76e847f49018cd3a80a3a13690f P a4262374090e4d0f870b4e85c77c179d [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: "a4262374090e4d0f870b4e85c77c179d" member_type: VOTER last_known_addr { host: "127.3.215.65" port: 44491 } }
I20260812 06:16:59.002866  4570 raft_consensus.cc:399] T 1f1ab76e847f49018cd3a80a3a13690f P a4262374090e4d0f870b4e85c77c179d [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:59.002913  4570 raft_consensus.cc:493] T 1f1ab76e847f49018cd3a80a3a13690f P a4262374090e4d0f870b4e85c77c179d [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:59.002970  4570 raft_consensus.cc:3060] T 1f1ab76e847f49018cd3a80a3a13690f P a4262374090e4d0f870b4e85c77c179d [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:59.003686  4570 raft_consensus.cc:515] T 1f1ab76e847f49018cd3a80a3a13690f P a4262374090e4d0f870b4e85c77c179d [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a4262374090e4d0f870b4e85c77c179d" member_type: VOTER last_known_addr { host: "127.3.215.65" port: 44491 } }
I20260812 06:16:59.003846  4570 leader_election.cc:304] T 1f1ab76e847f49018cd3a80a3a13690f P a4262374090e4d0f870b4e85c77c179d [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: a4262374090e4d0f870b4e85c77c179d; no voters: 
I20260812 06:16:59.004069  4570 leader_election.cc:290] T 1f1ab76e847f49018cd3a80a3a13690f P a4262374090e4d0f870b4e85c77c179d [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:59.004156  4572 raft_consensus.cc:2804] T 1f1ab76e847f49018cd3a80a3a13690f P a4262374090e4d0f870b4e85c77c179d [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:59.004376  4572 raft_consensus.cc:697] T 1f1ab76e847f49018cd3a80a3a13690f P a4262374090e4d0f870b4e85c77c179d [term 1 LEADER]: Becoming Leader. State: Replica: a4262374090e4d0f870b4e85c77c179d, State: Running, Role: LEADER
I20260812 06:16:59.004411  4550 heartbeater.cc:499] Master 127.3.215.126:43287 was elected leader, sending a full tablet report...
I20260812 06:16:59.004413  4570 ts_tablet_manager.cc:1434] T 1f1ab76e847f49018cd3a80a3a13690f P a4262374090e4d0f870b4e85c77c179d: Time spent starting tablet: real 0.002s	user 0.000s	sys 0.003s
I20260812 06:16:59.004532  4572 consensus_queue.cc:237] T 1f1ab76e847f49018cd3a80a3a13690f P a4262374090e4d0f870b4e85c77c179d [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: "a4262374090e4d0f870b4e85c77c179d" member_type: VOTER last_known_addr { host: "127.3.215.65" port: 44491 } }
I20260812 06:16:59.005884  4327 catalog_manager.cc:5719] T 1f1ab76e847f49018cd3a80a3a13690f P a4262374090e4d0f870b4e85c77c179d reported cstate change: term changed from 0 to 1, leader changed from <none> to a4262374090e4d0f870b4e85c77c179d (127.3.215.65). New cstate: current_term: 1 leader_uuid: "a4262374090e4d0f870b4e85c77c179d" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a4262374090e4d0f870b4e85c77c179d" member_type: VOTER last_known_addr { host: "127.3.215.65" port: 44491 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:59.063370  3933 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.054s	user 0.019s	sys 0.004s
I20260812 06:16:59.223191  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling FlushMRSOp(1f1ab76e847f49018cd3a80a3a13690f): perf score=19.054940
I20260812 06:16:59.380654  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: FlushMRSOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.157s	user 0.100s	sys 0.048s Metrics: {"bytes_written":9271708,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":63,"dirs.run_cpu_time_us":253,"dirs.run_wall_time_us":958,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":40524,"lbm_writes_lt_1ms":783,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1130}
I20260812 06:16:59.381311  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling LogGCOp(1f1ab76e847f49018cd3a80a3a13690f): free 20743880 bytes of WAL
I20260812 06:16:59.381553  4444 log_reader.cc:385] T 1f1ab76e847f49018cd3a80a3a13690f: removed 2 log segments from log reader
I20260812 06:16:59.381616  4444 log.cc:1079] T 1f1ab76e847f49018cd3a80a3a13690f P a4262374090e4d0f870b4e85c77c179d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/1f1ab76e847f49018cd3a80a3a13690f/wal-000000001 (ops 1-6)
I20260812 06:16:59.381676  4444 log.cc:1079] T 1f1ab76e847f49018cd3a80a3a13690f P a4262374090e4d0f870b4e85c77c179d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/1f1ab76e847f49018cd3a80a3a13690f/wal-000000002 (ops 7-11)
I20260812 06:16:59.386233  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: LogGCOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.005s	user 0.001s	sys 0.003s Metrics: {}
I20260812 06:16:59.386545  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling UndoDeltaBlockGCOp(1f1ab76e847f49018cd3a80a3a13690f): 20513799 bytes on disk
I20260812 06:16:59.387044  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: UndoDeltaBlockGCOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":86,"lbm_reads_lt_1ms":4}
I20260812 06:16:59.387619  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f): perf score=1.196750
I20260812 06:16:59.406704  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.019s	user 0.007s	sys 0.003s Metrics: {"bytes_written":3036005,"delete_count":0,"lbm_write_time_us":4356,"lbm_writes_lt_1ms":77,"reinsert_count":0,"update_count":370}
I20260812 06:16:59.407162  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f): perf score=2.188937
I20260812 06:16:59.418171  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4412,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:59.418603  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling MajorDeltaCompactionOp(1f1ab76e847f49018cd3a80a3a13690f): perf score=1.000000
I20260812 06:16:59.574189  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: MajorDeltaCompactionOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.155s	user 0.116s	sys 0.039s Metrics: {"cfile_cache_miss":433,"cfile_cache_miss_bytes":20672372,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":83,"lbm_read_time_us":13148,"lbm_reads_lt_1ms":469,"lbm_write_time_us":26054,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2560,"thread_start_us":341,"threads_started":5,"update_count":2000}
I20260812 06:16:59.574736  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f): perf score=10.126437
I20260812 06:16:59.620767  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.044s	user 0.014s	sys 0.027s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19683,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:59.621321  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f): perf score=2.188937
I20260812 06:16:59.632618  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4414,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:59.633275  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling MajorDeltaCompactionOp(1f1ab76e847f49018cd3a80a3a13690f): perf score=1.000000
I20260812 06:16:59.777601  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: MajorDeltaCompactionOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.144s	user 0.083s	sys 0.060s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":169,"lbm_read_time_us":10317,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23533,"lbm_writes_lt_1ms":443,"mutex_wait_us":25,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":19072,"update_count":2000}
I20260812 06:16:59.778120  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f): perf score=11.118625
I20260812 06:16:59.822405  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.044s	user 0.017s	sys 0.024s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":19102,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:59.822849  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f): perf score=2.188937
I20260812 06:16:59.849107  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.026s	user 0.005s	sys 0.015s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4110,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":500}
I20260812 06:16:59.849617  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f): perf score=2.188937
I20260812 06:16:59.859292  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3749,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:59.859720  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling MajorDeltaCompactionOp(1f1ab76e847f49018cd3a80a3a13690f): perf score=1.000000
I20260812 06:17:00.053864  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: MajorDeltaCompactionOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.194s	user 0.125s	sys 0.059s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":238,"lbm_read_time_us":13567,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29471,"lbm_writes_lt_1ms":543,"mutex_wait_us":42,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6144,"update_count":2500}
I20260812 06:17:00.054574  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f): perf score=14.095187
I20260812 06:17:00.109959  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.055s	user 0.019s	sys 0.035s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":26651,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":400,"reinsert_count":0,"update_count":2000}
I20260812 06:17:00.110473  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f): perf score=2.188937
I20260812 06:17:00.135246  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.025s	user 0.018s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5426,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":500}
I20260812 06:17:00.135813  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling MajorDeltaCompactionOp(1f1ab76e847f49018cd3a80a3a13690f): perf score=1.000000
I20260812 06:17:00.317646  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: MajorDeltaCompactionOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.182s	user 0.144s	sys 0.037s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":290,"lbm_read_time_us":13691,"lbm_reads_lt_1ms":564,"lbm_write_time_us":28900,"lbm_writes_lt_1ms":543,"mutex_wait_us":53,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7936,"update_count":2500}
I20260812 06:17:00.319425  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f): perf score=14.095187
I20260812 06:17:00.370293  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.051s	user 0.037s	sys 0.011s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22682,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:00.370954  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f): perf score=2.188937
I20260812 06:17:00.389233  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.018s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5602,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:00.389711  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f): perf score=2.188937
I20260812 06:17:00.412973  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.023s	user 0.008s	sys 0.015s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4374,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:00.413609  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling MajorDeltaCompactionOp(1f1ab76e847f49018cd3a80a3a13690f): perf score=1.000000
I20260812 06:17:00.636969  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: MajorDeltaCompactionOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.223s	user 0.147s	sys 0.072s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877218,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":574,"lbm_read_time_us":15542,"lbm_reads_lt_1ms":673,"lbm_write_time_us":39814,"lbm_writes_lt_1ms":643,"mutex_wait_us":19,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":5760,"update_count":3000}
I20260812 06:17:00.637686  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f): perf score=15.087375
I20260812 06:17:00.690768  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.053s	user 0.023s	sys 0.027s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":17912,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:17:00.691375  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f): perf score=2.188937
I20260812 06:17:00.702849  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3995,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:00.703521  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling FlushMRSOp(1f1ab76e847f49018cd3a80a3a13690f): perf score=1.000000
I20260812 06:17:00.739801  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: FlushMRSOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.036s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":67,"dirs.run_cpu_time_us":221,"dirs.run_wall_time_us":1535,"drs_written":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2060,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:17:00.740379  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling LogGCOp(1f1ab76e847f49018cd3a80a3a13690f): free 121006430 bytes of WAL
I20260812 06:17:00.740607  4444 log_reader.cc:385] T 1f1ab76e847f49018cd3a80a3a13690f: removed 12 log segments from log reader
I20260812 06:17:00.740651  4444 log.cc:1079] T 1f1ab76e847f49018cd3a80a3a13690f P a4262374090e4d0f870b4e85c77c179d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/1f1ab76e847f49018cd3a80a3a13690f/wal-000000003 (ops 12-16)
I20260812 06:17:00.740679  4444 log.cc:1079] T 1f1ab76e847f49018cd3a80a3a13690f P a4262374090e4d0f870b4e85c77c179d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/1f1ab76e847f49018cd3a80a3a13690f/wal-000000004 (ops 17-21)
I20260812 06:17:00.740741  4444 log.cc:1079] T 1f1ab76e847f49018cd3a80a3a13690f P a4262374090e4d0f870b4e85c77c179d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/1f1ab76e847f49018cd3a80a3a13690f/wal-000000005 (ops 22-26)
I20260812 06:17:00.740806  4444 log.cc:1079] T 1f1ab76e847f49018cd3a80a3a13690f P a4262374090e4d0f870b4e85c77c179d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/1f1ab76e847f49018cd3a80a3a13690f/wal-000000006 (ops 27-31)
I20260812 06:17:00.740871  4444 log.cc:1079] T 1f1ab76e847f49018cd3a80a3a13690f P a4262374090e4d0f870b4e85c77c179d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/1f1ab76e847f49018cd3a80a3a13690f/wal-000000007 (ops 32-36)
I20260812 06:17:00.740911  4444 log.cc:1079] T 1f1ab76e847f49018cd3a80a3a13690f P a4262374090e4d0f870b4e85c77c179d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/1f1ab76e847f49018cd3a80a3a13690f/wal-000000008 (ops 37-41)
I20260812 06:17:00.740967  4444 log.cc:1079] T 1f1ab76e847f49018cd3a80a3a13690f P a4262374090e4d0f870b4e85c77c179d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/1f1ab76e847f49018cd3a80a3a13690f/wal-000000009 (ops 42-46)
I20260812 06:17:00.741006  4444 log.cc:1079] T 1f1ab76e847f49018cd3a80a3a13690f P a4262374090e4d0f870b4e85c77c179d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/1f1ab76e847f49018cd3a80a3a13690f/wal-000000010 (ops 47-51)
I20260812 06:17:00.741044  4444 log.cc:1079] T 1f1ab76e847f49018cd3a80a3a13690f P a4262374090e4d0f870b4e85c77c179d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/1f1ab76e847f49018cd3a80a3a13690f/wal-000000011 (ops 52-56)
I20260812 06:17:00.741083  4444 log.cc:1079] T 1f1ab76e847f49018cd3a80a3a13690f P a4262374090e4d0f870b4e85c77c179d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/1f1ab76e847f49018cd3a80a3a13690f/wal-000000012 (ops 57-60)
I20260812 06:17:00.741120  4444 log.cc:1079] T 1f1ab76e847f49018cd3a80a3a13690f P a4262374090e4d0f870b4e85c77c179d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/1f1ab76e847f49018cd3a80a3a13690f/wal-000000013 (ops 61-65)
I20260812 06:17:00.741158  4444 log.cc:1079] T 1f1ab76e847f49018cd3a80a3a13690f P a4262374090e4d0f870b4e85c77c179d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/1f1ab76e847f49018cd3a80a3a13690f/wal-000000014 (ops 66-70)
I20260812 06:17:00.767936  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: LogGCOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.027s	user 0.002s	sys 0.023s Metrics: {}
I20260812 06:17:00.768319  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling UndoDeltaBlockGCOp(1f1ab76e847f49018cd3a80a3a13690f): 472 bytes on disk
I20260812 06:17:00.768739  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: UndoDeltaBlockGCOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4}
I20260812 06:17:00.769239  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f): perf score=3.181125
I20260812 06:17:00.787407  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.018s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4516,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:00.787870  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f): perf score=2.188937
I20260812 06:17:00.797152  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.009s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3500,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:00.797683  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling MajorDeltaCompactionOp(1f1ab76e847f49018cd3a80a3a13690f): perf score=1.000000
I20260812 06:17:01.051664  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: MajorDeltaCompactionOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.254s	user 0.137s	sys 0.097s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979727,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":284,"lbm_read_time_us":16382,"lbm_reads_lt_1ms":774,"lbm_write_time_us":39058,"lbm_writes_lt_1ms":743,"mutex_wait_us":42,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":35840,"thread_start_us":89,"threads_started":1,"update_count":3500}
I20260812 06:17:01.052345  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f): perf score=18.063937
I20260812 06:17:01.120582  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.068s	user 0.040s	sys 0.023s Metrics: {"bytes_written":20512318,"delete_count":0,"lbm_write_time_us":30164,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:01.121042  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f): perf score=2.188937
I20260812 06:17:01.131198  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3967,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:01.131681  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling MajorDeltaCompactionOp(1f1ab76e847f49018cd3a80a3a13690f): perf score=1.000000
I20260812 06:17:01.323882  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: MajorDeltaCompactionOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.192s	user 0.132s	sys 0.056s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877105,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":277,"lbm_read_time_us":14504,"lbm_reads_lt_1ms":672,"lbm_write_time_us":32428,"lbm_writes_lt_1ms":643,"mutex_wait_us":65,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":20736,"update_count":3000}
I20260812 06:17:01.324595  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f): perf score=15.087375
I20260812 06:17:01.380249  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.055s	user 0.035s	sys 0.015s Metrics: {"bytes_written":16820176,"delete_count":0,"lbm_write_time_us":23426,"lbm_writes_lt_1ms":413,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":2050}
I20260812 06:17:01.380910  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f): perf score=2.188937
I20260812 06:17:01.392401  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4260,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:01.392927  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f): perf score=2.188937
I20260812 06:17:01.402889  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3778,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:01.403357  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling MajorDeltaCompactionOp(1f1ab76e847f49018cd3a80a3a13690f): perf score=1.000000
I20260812 06:17:01.571529  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: MajorDeltaCompactionOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.168s	user 0.132s	sys 0.036s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877240,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":328,"lbm_read_time_us":11677,"lbm_reads_lt_1ms":673,"lbm_write_time_us":34861,"lbm_writes_lt_1ms":643,"mutex_wait_us":67,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":11648,"update_count":3000}
I20260812 06:17:01.572329  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f): perf score=14.095187
I20260812 06:17:01.618417  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.046s	user 0.017s	sys 0.027s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":20288,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:01.618963  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f): perf score=2.188937
I20260812 06:17:01.634577  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.015s	user 0.009s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6255,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:01.635011  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling MajorDeltaCompactionOp(1f1ab76e847f49018cd3a80a3a13690f): perf score=1.000000
I20260812 06:17:01.791806  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: MajorDeltaCompactionOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.157s	user 0.108s	sys 0.038s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1293,"lbm_read_time_us":9859,"lbm_reads_lt_1ms":564,"lbm_write_time_us":28337,"lbm_writes_lt_1ms":543,"mutex_wait_us":391,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5376,"update_count":2500}
I20260812 06:17:01.792469  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f): perf score=14.095187
I20260812 06:17:01.830735  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.038s	user 0.029s	sys 0.007s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":17298,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:01.831264  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling MajorDeltaCompactionOp(1f1ab76e847f49018cd3a80a3a13690f): perf score=1.000000
I20260812 06:17:01.982156  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: MajorDeltaCompactionOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.151s	user 0.114s	sys 0.036s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672158,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":718,"lbm_read_time_us":12971,"lbm_reads_lt_1ms":467,"lbm_write_time_us":24578,"lbm_writes_lt_1ms":443,"mutex_wait_us":365,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":31360,"update_count":2000}
I20260812 06:17:01.982899  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f): perf score=10.126437
I20260812 06:17:02.023703  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.041s	user 0.020s	sys 0.011s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14611,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:02.024338  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f): perf score=2.188937
I20260812 06:17:02.041296  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.017s	user 0.013s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6281,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:02.042068  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling MajorDeltaCompactionOp(1f1ab76e847f49018cd3a80a3a13690f): perf score=1.000000
I20260812 06:17:02.175499  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: MajorDeltaCompactionOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.133s	user 0.109s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":162,"lbm_read_time_us":7888,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26909,"lbm_writes_lt_1ms":443,"mutex_wait_us":39,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":22144,"update_count":2000}
I20260812 06:17:02.176322  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f): perf score=10.126437
I20260812 06:17:02.211509  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.035s	user 0.022s	sys 0.008s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":14204,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:02.212163  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f): perf score=2.188937
I20260812 06:17:02.227471  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.015s	user 0.009s	sys 0.003s Metrics: {"bytes_written":4102660,"delete_count":0,"lbm_write_time_us":5630,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:02.228068  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling FlushMRSOp(1f1ab76e847f49018cd3a80a3a13690f): perf score=1.000000
I20260812 06:17:02.260068  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: FlushMRSOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.032s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":87,"dirs.run_cpu_time_us":210,"dirs.run_wall_time_us":1544,"drs_written":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2346,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:02.260825  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling LogGCOp(1f1ab76e847f49018cd3a80a3a13690f): free 127961115 bytes of WAL
I20260812 06:17:02.261090  4444 log_reader.cc:385] T 1f1ab76e847f49018cd3a80a3a13690f: removed 12 log segments from log reader
I20260812 06:17:02.261161  4444 log.cc:1079] T 1f1ab76e847f49018cd3a80a3a13690f P a4262374090e4d0f870b4e85c77c179d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/1f1ab76e847f49018cd3a80a3a13690f/wal-000000015 (ops 71-75)
I20260812 06:17:02.261204  4444 log.cc:1079] T 1f1ab76e847f49018cd3a80a3a13690f P a4262374090e4d0f870b4e85c77c179d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/1f1ab76e847f49018cd3a80a3a13690f/wal-000000016 (ops 76-80)
I20260812 06:17:02.261243  4444 log.cc:1079] T 1f1ab76e847f49018cd3a80a3a13690f P a4262374090e4d0f870b4e85c77c179d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/1f1ab76e847f49018cd3a80a3a13690f/wal-000000017 (ops 81-85)
I20260812 06:17:02.261286  4444 log.cc:1079] T 1f1ab76e847f49018cd3a80a3a13690f P a4262374090e4d0f870b4e85c77c179d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/1f1ab76e847f49018cd3a80a3a13690f/wal-000000018 (ops 86-90)
I20260812 06:17:02.261333  4444 log.cc:1079] T 1f1ab76e847f49018cd3a80a3a13690f P a4262374090e4d0f870b4e85c77c179d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/1f1ab76e847f49018cd3a80a3a13690f/wal-000000019 (ops 91-95)
I20260812 06:17:02.261370  4444 log.cc:1079] T 1f1ab76e847f49018cd3a80a3a13690f P a4262374090e4d0f870b4e85c77c179d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/1f1ab76e847f49018cd3a80a3a13690f/wal-000000020 (ops 96-100)
I20260812 06:17:02.261409  4444 log.cc:1079] T 1f1ab76e847f49018cd3a80a3a13690f P a4262374090e4d0f870b4e85c77c179d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/1f1ab76e847f49018cd3a80a3a13690f/wal-000000021 (ops 101-105)
I20260812 06:17:02.261449  4444 log.cc:1079] T 1f1ab76e847f49018cd3a80a3a13690f P a4262374090e4d0f870b4e85c77c179d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/1f1ab76e847f49018cd3a80a3a13690f/wal-000000022 (ops 106-110)
I20260812 06:17:02.261488  4444 log.cc:1079] T 1f1ab76e847f49018cd3a80a3a13690f P a4262374090e4d0f870b4e85c77c179d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/1f1ab76e847f49018cd3a80a3a13690f/wal-000000023 (ops 111-115)
I20260812 06:17:02.261524  4444 log.cc:1079] T 1f1ab76e847f49018cd3a80a3a13690f P a4262374090e4d0f870b4e85c77c179d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/1f1ab76e847f49018cd3a80a3a13690f/wal-000000024 (ops 116-120)
I20260812 06:17:02.261560  4444 log.cc:1079] T 1f1ab76e847f49018cd3a80a3a13690f P a4262374090e4d0f870b4e85c77c179d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/1f1ab76e847f49018cd3a80a3a13690f/wal-000000025 (ops 121-125)
I20260812 06:17:02.261601  4444 log.cc:1079] T 1f1ab76e847f49018cd3a80a3a13690f P a4262374090e4d0f870b4e85c77c179d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/1f1ab76e847f49018cd3a80a3a13690f/wal-000000026 (ops 126-130)
I20260812 06:17:02.294837  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: LogGCOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.034s	user 0.008s	sys 0.024s Metrics: {}
I20260812 06:17:02.295293  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling UndoDeltaBlockGCOp(1f1ab76e847f49018cd3a80a3a13690f): 482 bytes on disk
I20260812 06:17:02.295954  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: UndoDeltaBlockGCOp(1f1ab76e847f49018cd3a80a3a13690f) 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:17:02.296664  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f): perf score=2.188937
I20260812 06:17:02.316220  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.019s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4587,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:02.316730  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f): perf score=2.188937
I20260812 06:17:02.327080  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3999,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:02.327662  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling MajorDeltaCompactionOp(1f1ab76e847f49018cd3a80a3a13690f): perf score=1.000000
I20260812 06:17:02.511389  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: MajorDeltaCompactionOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.184s	user 0.129s	sys 0.049s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877338,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":271,"lbm_read_time_us":13752,"lbm_reads_lt_1ms":674,"lbm_write_time_us":38698,"lbm_writes_lt_1ms":643,"mutex_wait_us":73,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":31488,"thread_start_us":75,"threads_started":1,"update_count":3000}
I20260812 06:17:02.512732  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f): perf score=14.095187
I20260812 06:17:02.566017  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.053s	user 0.027s	sys 0.016s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":19624,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:02.566536  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f): perf score=2.188937
I20260812 06:17:02.578099  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4158,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:02.578560  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling MajorDeltaCompactionOp(1f1ab76e847f49018cd3a80a3a13690f): perf score=1.000000
I20260812 06:17:02.732546  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: MajorDeltaCompactionOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.154s	user 0.115s	sys 0.033s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":374,"lbm_read_time_us":12437,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30139,"lbm_writes_lt_1ms":543,"mutex_wait_us":62,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2500}
I20260812 06:17:02.733201  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f): perf score=11.118625
I20260812 06:17:02.768765  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.035s	user 0.021s	sys 0.011s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15825,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:02.769333  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f): perf score=2.188937
I20260812 06:17:02.785737  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.016s	user 0.008s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5215,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:02.786288  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling MajorDeltaCompactionOp(1f1ab76e847f49018cd3a80a3a13690f): perf score=1.000000
I20260812 06:17:02.919956  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: MajorDeltaCompactionOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.133s	user 0.112s	sys 0.021s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":161,"lbm_read_time_us":9782,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25864,"lbm_writes_lt_1ms":443,"mutex_wait_us":50,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14720,"update_count":2000}
I20260812 06:17:02.920674  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f): perf score=10.126437
I20260812 06:17:02.958999  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.038s	user 0.019s	sys 0.012s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":14182,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:02.959545  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f): perf score=2.188937
I20260812 06:17:02.976876  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.017s	user 0.014s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6243,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:02.977566  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling MajorDeltaCompactionOp(1f1ab76e847f49018cd3a80a3a13690f): perf score=1.000000
I20260812 06:17:03.097348  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: MajorDeltaCompactionOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.119s	user 0.088s	sys 0.030s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":955,"lbm_read_time_us":8487,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23057,"lbm_writes_lt_1ms":443,"mutex_wait_us":373,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3712,"update_count":2000}
I20260812 06:17:03.098201  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f): perf score=10.126437
I20260812 06:17:03.145159  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.047s	user 0.033s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15592,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:03.145879  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f): perf score=2.188937
I20260812 06:17:03.156700  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4252,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:03.157193  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling MajorDeltaCompactionOp(1f1ab76e847f49018cd3a80a3a13690f): perf score=1.000000
I20260812 06:17:03.319198  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: MajorDeltaCompactionOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.162s	user 0.097s	sys 0.064s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1075,"lbm_read_time_us":10944,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24724,"lbm_writes_lt_1ms":443,"mutex_wait_us":331,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10496,"update_count":2000}
I20260812 06:17:03.319712  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f): perf score=10.126437
I20260812 06:17:03.363837  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.044s	user 0.015s	sys 0.023s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":18709,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:03.364424  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f): perf score=2.188937
I20260812 06:17:03.377364  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.013s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4777,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:03.377842  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling MajorDeltaCompactionOp(1f1ab76e847f49018cd3a80a3a13690f): perf score=1.000000
I20260812 06:17:03.504292  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: MajorDeltaCompactionOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.126s	user 0.093s	sys 0.033s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":806,"lbm_read_time_us":10867,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22445,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4864,"update_count":2000}
I20260812 06:17:03.505124  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f): perf score=10.126437
I20260812 06:17:03.542550  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.037s	user 0.023s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15569,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:03.543481  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f): perf score=2.188937
I20260812 06:17:03.560823  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.017s	user 0.007s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6301,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:03.561559  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling MajorDeltaCompactionOp(1f1ab76e847f49018cd3a80a3a13690f): perf score=1.000000
I20260812 06:17:03.696593  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: MajorDeltaCompactionOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.135s	user 0.114s	sys 0.021s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":153,"lbm_read_time_us":10678,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26786,"lbm_writes_lt_1ms":443,"mutex_wait_us":46,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12416,"update_count":2000}
I20260812 06:17:03.697433  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f): perf score=10.126437
I20260812 06:17:03.745904  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.048s	user 0.024s	sys 0.022s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15639,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:03.746418  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f): perf score=2.188937
I20260812 06:17:03.762490  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.016s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6180,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:03.763156  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling FlushMRSOp(1f1ab76e847f49018cd3a80a3a13690f): perf score=1.000000
I20260812 06:17:03.805302  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: FlushMRSOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.042s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":52,"dirs.run_cpu_time_us":186,"dirs.run_wall_time_us":1352,"drs_written":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1543,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:03.806087  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling LogGCOp(1f1ab76e847f49018cd3a80a3a13690f): free 133477650 bytes of WAL
I20260812 06:17:03.806340  4444 log_reader.cc:385] T 1f1ab76e847f49018cd3a80a3a13690f: removed 13 log segments from log reader
I20260812 06:17:03.806408  4444 log.cc:1079] T 1f1ab76e847f49018cd3a80a3a13690f P a4262374090e4d0f870b4e85c77c179d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/1f1ab76e847f49018cd3a80a3a13690f/wal-000000027 (ops 131-135)
I20260812 06:17:03.806456  4444 log.cc:1079] T 1f1ab76e847f49018cd3a80a3a13690f P a4262374090e4d0f870b4e85c77c179d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/1f1ab76e847f49018cd3a80a3a13690f/wal-000000028 (ops 136-140)
I20260812 06:17:03.806514  4444 log.cc:1079] T 1f1ab76e847f49018cd3a80a3a13690f P a4262374090e4d0f870b4e85c77c179d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/1f1ab76e847f49018cd3a80a3a13690f/wal-000000029 (ops 141-145)
I20260812 06:17:03.806559  4444 log.cc:1079] T 1f1ab76e847f49018cd3a80a3a13690f P a4262374090e4d0f870b4e85c77c179d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/1f1ab76e847f49018cd3a80a3a13690f/wal-000000030 (ops 146-150)
I20260812 06:17:03.806598  4444 log.cc:1079] T 1f1ab76e847f49018cd3a80a3a13690f P a4262374090e4d0f870b4e85c77c179d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/1f1ab76e847f49018cd3a80a3a13690f/wal-000000031 (ops 151-155)
I20260812 06:17:03.806638  4444 log.cc:1079] T 1f1ab76e847f49018cd3a80a3a13690f P a4262374090e4d0f870b4e85c77c179d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/1f1ab76e847f49018cd3a80a3a13690f/wal-000000032 (ops 156-160)
I20260812 06:17:03.806676  4444 log.cc:1079] T 1f1ab76e847f49018cd3a80a3a13690f P a4262374090e4d0f870b4e85c77c179d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/1f1ab76e847f49018cd3a80a3a13690f/wal-000000033 (ops 161-165)
I20260812 06:17:03.806715  4444 log.cc:1079] T 1f1ab76e847f49018cd3a80a3a13690f P a4262374090e4d0f870b4e85c77c179d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/1f1ab76e847f49018cd3a80a3a13690f/wal-000000034 (ops 166-170)
I20260812 06:17:03.806752  4444 log.cc:1079] T 1f1ab76e847f49018cd3a80a3a13690f P a4262374090e4d0f870b4e85c77c179d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/1f1ab76e847f49018cd3a80a3a13690f/wal-000000035 (ops 171-175)
I20260812 06:17:03.806790  4444 log.cc:1079] T 1f1ab76e847f49018cd3a80a3a13690f P a4262374090e4d0f870b4e85c77c179d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/1f1ab76e847f49018cd3a80a3a13690f/wal-000000036 (ops 176-180)
I20260812 06:17:03.806828  4444 log.cc:1079] T 1f1ab76e847f49018cd3a80a3a13690f P a4262374090e4d0f870b4e85c77c179d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/1f1ab76e847f49018cd3a80a3a13690f/wal-000000037 (ops 181-185)
I20260812 06:17:03.806866  4444 log.cc:1079] T 1f1ab76e847f49018cd3a80a3a13690f P a4262374090e4d0f870b4e85c77c179d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/1f1ab76e847f49018cd3a80a3a13690f/wal-000000038 (ops 186-190)
I20260812 06:17:03.806912  4444 log.cc:1079] T 1f1ab76e847f49018cd3a80a3a13690f P a4262374090e4d0f870b4e85c77c179d: Deleting log segment in path: /tmp/dist-test-task5kIQN_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515413432700-3933-0/minicluster-data/ts-0-root/wals/1f1ab76e847f49018cd3a80a3a13690f/wal-000000039 (ops 191-195)
I20260812 06:17:03.837782  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: LogGCOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.031s	user 0.004s	sys 0.027s Metrics: {}
I20260812 06:17:03.838231  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling UndoDeltaBlockGCOp(1f1ab76e847f49018cd3a80a3a13690f): 482 bytes on disk
I20260812 06:17:03.838743  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: UndoDeltaBlockGCOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":69,"lbm_reads_lt_1ms":4}
I20260812 06:17:03.839313  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f): perf score=3.181125
I20260812 06:17:03.853856  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.014s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4933,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:03.854341  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f): perf score=2.188937
I20260812 06:17:03.867650  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5101,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:03.868120  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling MajorDeltaCompactionOp(1f1ab76e847f49018cd3a80a3a13690f): perf score=1.000000
I20260812 06:17:03.961229  3933 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.898s	user 1.860s	sys 0.128s
I20260812 06:17:04.061826  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: MajorDeltaCompactionOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.193s	user 0.130s	sys 0.063s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877327,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":213,"lbm_read_time_us":15193,"lbm_reads_lt_1ms":670,"lbm_write_time_us":31596,"lbm_writes_lt_1ms":643,"mutex_wait_us":43,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":18304,"thread_start_us":79,"threads_started":1,"update_count":3000}
I20260812 06:17:04.062553  4551 maintenance_manager.cc:419] P a4262374090e4d0f870b4e85c77c179d: Scheduling FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f): perf score=6.157687
I20260812 06:17:04.064277  3933 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.103s	user 0.001s	sys 0.000s
I20260812 06:17:04.064906  3933 tablet_server.cc:179] TabletServer@127.3.215.65:0 shutting down...
I20260812 06:17:04.101682  4444 maintenance_manager.cc:643] P a4262374090e4d0f870b4e85c77c179d: FlushDeltaMemStoresOp(1f1ab76e847f49018cd3a80a3a13690f) complete. Timing: real 0.039s	user 0.023s	sys 0.015s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":10134,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:17:04.103472  3933 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:04.103725  3933 tablet_replica.cc:333] T 1f1ab76e847f49018cd3a80a3a13690f P a4262374090e4d0f870b4e85c77c179d: stopping tablet replica
I20260812 06:17:04.103904  3933 raft_consensus.cc:2243] T 1f1ab76e847f49018cd3a80a3a13690f P a4262374090e4d0f870b4e85c77c179d [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:04.104097  3933 raft_consensus.cc:2272] T 1f1ab76e847f49018cd3a80a3a13690f P a4262374090e4d0f870b4e85c77c179d [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:04.117802  3933 tablet_server.cc:196] TabletServer@127.3.215.65:0 shutdown complete.
I20260812 06:17:04.120553  3933 master.cc:562] Master@127.3.215.126:43287 shutting down...
I20260812 06:17:04.124054  3933 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 29853d923a6846cc943a7a246c669d3c [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:04.124240  3933 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 29853d923a6846cc943a7a246c669d3c [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:04.124323  3933 tablet_replica.cc:333] T 00000000000000000000000000000000 P 29853d923a6846cc943a7a246c669d3c: stopping tablet replica
I20260812 06:17:04.137069  3933 master.cc:584] Master@127.3.215.126:43287 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5353 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10786 ms total)

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