[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:18:40.412887  7292 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.7.31.62:34565
I20260812 06:18:40.414054  7292 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:18:40.414744  7292 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:40.422183  7299 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:40.422186  7304 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:40.422245  7292 server_base.cc:1061] running on GCE node
W20260812 06:18:40.422501  7301 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:40.423170  7292 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:40.423280  7292 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:40.423348  7292 hybrid_clock.cc:648] HybridClock initialized: now 1786515520423344 us; error 0 us; skew 500 ppm
I20260812 06:18:40.425398  7292 webserver.cc:533] Webserver started at http://127.7.31.62:45407/ using document root <none> and password file <none>
I20260812 06:18:40.426069  7292 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:40.426131  7292 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:40.426395  7292 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:40.428216  7292 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520401731-7292-0/minicluster-data/master-0-root/instance:
uuid: "5fed1f6818ca4439957e8c0e26b87469"
format_stamp: "Formatted at 2026-08-12 06:18:40 on dist-test-slave-8tdl"
I20260812 06:18:40.432369  7292 fs_manager.cc:696] Time spent creating directory manager: real 0.004s	user 0.005s	sys 0.000s
I20260812 06:18:40.435186  7309 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:40.436393  7292 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:18:40.436544  7292 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520401731-7292-0/minicluster-data/master-0-root
uuid: "5fed1f6818ca4439957e8c0e26b87469"
format_stamp: "Formatted at 2026-08-12 06:18:40 on dist-test-slave-8tdl"
I20260812 06:18:40.436663  7292 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520401731-7292-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520401731-7292-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520401731-7292-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:40.449219  7292 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:40.449939  7292 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:18:40.450147  7292 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:40.458788  7292 rpc_server.cc:307] RPC server started. Bound to: 127.7.31.62:34565
I20260812 06:18:40.458793  7365 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.7.31.62:34565 every 8 connection(s)
I20260812 06:18:40.461690  7366 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:40.467984  7366 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 5fed1f6818ca4439957e8c0e26b87469: Bootstrap starting.
I20260812 06:18:40.470503  7366 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 5fed1f6818ca4439957e8c0e26b87469: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:40.471527  7366 log.cc:826] T 00000000000000000000000000000000 P 5fed1f6818ca4439957e8c0e26b87469: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:40.473553  7366 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 5fed1f6818ca4439957e8c0e26b87469: No bootstrap required, opened a new log
I20260812 06:18:40.477078  7366 raft_consensus.cc:359] T 00000000000000000000000000000000 P 5fed1f6818ca4439957e8c0e26b87469 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5fed1f6818ca4439957e8c0e26b87469" member_type: VOTER }
I20260812 06:18:40.477370  7366 raft_consensus.cc:385] T 00000000000000000000000000000000 P 5fed1f6818ca4439957e8c0e26b87469 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:40.477473  7366 raft_consensus.cc:740] T 00000000000000000000000000000000 P 5fed1f6818ca4439957e8c0e26b87469 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 5fed1f6818ca4439957e8c0e26b87469, State: Initialized, Role: FOLLOWER
I20260812 06:18:40.478238  7366 consensus_queue.cc:260] T 00000000000000000000000000000000 P 5fed1f6818ca4439957e8c0e26b87469 [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: "5fed1f6818ca4439957e8c0e26b87469" member_type: VOTER }
I20260812 06:18:40.478516  7366 raft_consensus.cc:399] T 00000000000000000000000000000000 P 5fed1f6818ca4439957e8c0e26b87469 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:40.478595  7366 raft_consensus.cc:493] T 00000000000000000000000000000000 P 5fed1f6818ca4439957e8c0e26b87469 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:40.478811  7366 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 5fed1f6818ca4439957e8c0e26b87469 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:40.479773  7366 raft_consensus.cc:515] T 00000000000000000000000000000000 P 5fed1f6818ca4439957e8c0e26b87469 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5fed1f6818ca4439957e8c0e26b87469" member_type: VOTER }
I20260812 06:18:40.480360  7366 leader_election.cc:304] T 00000000000000000000000000000000 P 5fed1f6818ca4439957e8c0e26b87469 [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: 5fed1f6818ca4439957e8c0e26b87469; no voters: 
I20260812 06:18:40.480753  7366 leader_election.cc:290] T 00000000000000000000000000000000 P 5fed1f6818ca4439957e8c0e26b87469 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:40.480928  7370 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 5fed1f6818ca4439957e8c0e26b87469 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:40.481204  7370 raft_consensus.cc:697] T 00000000000000000000000000000000 P 5fed1f6818ca4439957e8c0e26b87469 [term 1 LEADER]: Becoming Leader. State: Replica: 5fed1f6818ca4439957e8c0e26b87469, State: Running, Role: LEADER
I20260812 06:18:40.481724  7370 consensus_queue.cc:237] T 00000000000000000000000000000000 P 5fed1f6818ca4439957e8c0e26b87469 [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: "5fed1f6818ca4439957e8c0e26b87469" member_type: VOTER }
I20260812 06:18:40.481977  7366 sys_catalog.cc:565] T 00000000000000000000000000000000 P 5fed1f6818ca4439957e8c0e26b87469 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:40.483842  7371 sys_catalog.cc:455] T 00000000000000000000000000000000 P 5fed1f6818ca4439957e8c0e26b87469 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "5fed1f6818ca4439957e8c0e26b87469" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5fed1f6818ca4439957e8c0e26b87469" member_type: VOTER } }
I20260812 06:18:40.483896  7372 sys_catalog.cc:455] T 00000000000000000000000000000000 P 5fed1f6818ca4439957e8c0e26b87469 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 5fed1f6818ca4439957e8c0e26b87469. Latest consensus state: current_term: 1 leader_uuid: "5fed1f6818ca4439957e8c0e26b87469" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5fed1f6818ca4439957e8c0e26b87469" member_type: VOTER } }
I20260812 06:18:40.483982  7371 sys_catalog.cc:458] T 00000000000000000000000000000000 P 5fed1f6818ca4439957e8c0e26b87469 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:40.484001  7372 sys_catalog.cc:458] T 00000000000000000000000000000000 P 5fed1f6818ca4439957e8c0e26b87469 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:40.484550  7388 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:40.484704  7292 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:40.487416  7388 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:40.493462  7388 catalog_manager.cc:1383] Generated new cluster ID: cef620f6450c456a981778ddca8bf364
I20260812 06:18:40.493587  7388 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:40.510366  7388 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:40.511449  7388 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:40.517838  7388 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 5fed1f6818ca4439957e8c0e26b87469: Generated new TSK 0
I20260812 06:18:40.518832  7388 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:40.550146  7292 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:40.553292  7402 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:40.553365  7399 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:40.553292  7398 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:40.553788  7292 server_base.cc:1061] running on GCE node
I20260812 06:18:40.553978  7292 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:40.554028  7292 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:40.554052  7292 hybrid_clock.cc:648] HybridClock initialized: now 1786515520554052 us; error 0 us; skew 500 ppm
I20260812 06:18:40.555101  7292 webserver.cc:533] Webserver started at http://127.7.31.1:37307/ using document root <none> and password file <none>
I20260812 06:18:40.555286  7292 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:40.555359  7292 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:40.555447  7292 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:40.556689  7292 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520401731-7292-0/minicluster-data/ts-0-root/instance:
uuid: "55d61543782041b8b54cd0059dfe8a10"
format_stamp: "Formatted at 2026-08-12 06:18:40 on dist-test-slave-8tdl"
I20260812 06:18:40.561177  7292 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.003s	sys 0.003s
I20260812 06:18:40.562460  7408 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:40.562808  7292 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:40.562876  7292 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520401731-7292-0/minicluster-data/ts-0-root
uuid: "55d61543782041b8b54cd0059dfe8a10"
format_stamp: "Formatted at 2026-08-12 06:18:40 on dist-test-slave-8tdl"
I20260812 06:18:40.563023  7292 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520401731-7292-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520401731-7292-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520401731-7292-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:40.575579  7292 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:40.576154  7292 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:40.576906  7292 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:40.577791  7292 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:40.577842  7292 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:40.577914  7292 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:40.577958  7292 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:40.585168  7292 rpc_server.cc:307] RPC server started. Bound to: 127.7.31.1:45697
I20260812 06:18:40.585246  7476 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.7.31.1:45697 every 8 connection(s)
I20260812 06:18:40.596885  7477 heartbeater.cc:344] Connected to a master server at 127.7.31.62:34565
I20260812 06:18:40.597198  7477 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:40.597697  7477 heartbeater.cc:507] Master 127.7.31.62:34565 requested a full tablet report, sending...
I20260812 06:18:40.599366  7327 ts_manager.cc:194] Registered new tserver with Master: 55d61543782041b8b54cd0059dfe8a10 (127.7.31.1:45697)
I20260812 06:18:40.599833  7292 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.013474531s
I20260812 06:18:40.600942  7327 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:34848
I20260812 06:18:40.611960  7327 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:34856:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:40.626945  7437 tablet_service.cc:1511] Processing CreateTablet for tablet 65d6fb310f214215b638e04ecd3296f7 (DEFAULT_TABLE table=heavy-update-compaction-test [id=c097f667ee034747bfeff4c147d97129]), partition=
I20260812 06:18:40.627478  7437 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 65d6fb310f214215b638e04ecd3296f7. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:40.629906  7492 tablet_bootstrap.cc:492] T 65d6fb310f214215b638e04ecd3296f7 P 55d61543782041b8b54cd0059dfe8a10: Bootstrap starting.
I20260812 06:18:40.631145  7492 tablet_bootstrap.cc:654] T 65d6fb310f214215b638e04ecd3296f7 P 55d61543782041b8b54cd0059dfe8a10: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:40.632479  7492 tablet_bootstrap.cc:492] T 65d6fb310f214215b638e04ecd3296f7 P 55d61543782041b8b54cd0059dfe8a10: No bootstrap required, opened a new log
I20260812 06:18:40.632608  7492 ts_tablet_manager.cc:1403] T 65d6fb310f214215b638e04ecd3296f7 P 55d61543782041b8b54cd0059dfe8a10: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:18:40.633244  7492 raft_consensus.cc:359] T 65d6fb310f214215b638e04ecd3296f7 P 55d61543782041b8b54cd0059dfe8a10 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "55d61543782041b8b54cd0059dfe8a10" member_type: VOTER last_known_addr { host: "127.7.31.1" port: 45697 } }
I20260812 06:18:40.633379  7492 raft_consensus.cc:385] T 65d6fb310f214215b638e04ecd3296f7 P 55d61543782041b8b54cd0059dfe8a10 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:40.633435  7492 raft_consensus.cc:740] T 65d6fb310f214215b638e04ecd3296f7 P 55d61543782041b8b54cd0059dfe8a10 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 55d61543782041b8b54cd0059dfe8a10, State: Initialized, Role: FOLLOWER
I20260812 06:18:40.633600  7492 consensus_queue.cc:260] T 65d6fb310f214215b638e04ecd3296f7 P 55d61543782041b8b54cd0059dfe8a10 [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: "55d61543782041b8b54cd0059dfe8a10" member_type: VOTER last_known_addr { host: "127.7.31.1" port: 45697 } }
I20260812 06:18:40.633770  7492 raft_consensus.cc:399] T 65d6fb310f214215b638e04ecd3296f7 P 55d61543782041b8b54cd0059dfe8a10 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:40.633831  7492 raft_consensus.cc:493] T 65d6fb310f214215b638e04ecd3296f7 P 55d61543782041b8b54cd0059dfe8a10 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:40.633972  7492 raft_consensus.cc:3060] T 65d6fb310f214215b638e04ecd3296f7 P 55d61543782041b8b54cd0059dfe8a10 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:40.634917  7492 raft_consensus.cc:515] T 65d6fb310f214215b638e04ecd3296f7 P 55d61543782041b8b54cd0059dfe8a10 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "55d61543782041b8b54cd0059dfe8a10" member_type: VOTER last_known_addr { host: "127.7.31.1" port: 45697 } }
I20260812 06:18:40.635078  7492 leader_election.cc:304] T 65d6fb310f214215b638e04ecd3296f7 P 55d61543782041b8b54cd0059dfe8a10 [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: 55d61543782041b8b54cd0059dfe8a10; no voters: 
I20260812 06:18:40.635362  7492 leader_election.cc:290] T 65d6fb310f214215b638e04ecd3296f7 P 55d61543782041b8b54cd0059dfe8a10 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:40.635486  7494 raft_consensus.cc:2804] T 65d6fb310f214215b638e04ecd3296f7 P 55d61543782041b8b54cd0059dfe8a10 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:40.635748  7494 raft_consensus.cc:697] T 65d6fb310f214215b638e04ecd3296f7 P 55d61543782041b8b54cd0059dfe8a10 [term 1 LEADER]: Becoming Leader. State: Replica: 55d61543782041b8b54cd0059dfe8a10, State: Running, Role: LEADER
I20260812 06:18:40.635778  7492 ts_tablet_manager.cc:1434] T 65d6fb310f214215b638e04ecd3296f7 P 55d61543782041b8b54cd0059dfe8a10: Time spent starting tablet: real 0.003s	user 0.002s	sys 0.002s
I20260812 06:18:40.635970  7494 consensus_queue.cc:237] T 65d6fb310f214215b638e04ecd3296f7 P 55d61543782041b8b54cd0059dfe8a10 [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: "55d61543782041b8b54cd0059dfe8a10" member_type: VOTER last_known_addr { host: "127.7.31.1" port: 45697 } }
I20260812 06:18:40.636024  7477 heartbeater.cc:499] Master 127.7.31.62:34565 was elected leader, sending a full tablet report...
I20260812 06:18:40.639202  7327 catalog_manager.cc:5719] T 65d6fb310f214215b638e04ecd3296f7 P 55d61543782041b8b54cd0059dfe8a10 reported cstate change: term changed from 0 to 1, leader changed from <none> to 55d61543782041b8b54cd0059dfe8a10 (127.7.31.1). New cstate: current_term: 1 leader_uuid: "55d61543782041b8b54cd0059dfe8a10" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "55d61543782041b8b54cd0059dfe8a10" member_type: VOTER last_known_addr { host: "127.7.31.1" port: 45697 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:40.721983  7292 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.075s	user 0.022s	sys 0.015s
I20260812 06:18:40.836956  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling FlushMRSOp(65d6fb310f214215b638e04ecd3296f7): perf score=15.086190
I20260812 06:18:41.050068  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: FlushMRSOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.213s	user 0.143s	sys 0.056s Metrics: {"bytes_written":12307490,"cfile_init":1,"compiler_manager_pool.queue_time_us":315,"delete_count":0,"dirs.queue_time_us":50,"dirs.run_cpu_time_us":221,"dirs.run_wall_time_us":1350,"drs_written":1,"lbm_read_time_us":93,"lbm_reads_lt_1ms":4,"lbm_write_time_us":54797,"lbm_writes_lt_1ms":657,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"spinlock_wait_cycles":1920,"thread_start_us":187,"threads_started":1,"update_count":1500}
I20260812 06:18:41.051578  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling LogGCOp(65d6fb310f214215b638e04ecd3296f7): free 8725963 bytes of WAL
I20260812 06:18:41.051913  7413 log_reader.cc:385] T 65d6fb310f214215b638e04ecd3296f7: removed 1 log segments from log reader
I20260812 06:18:41.051990  7413 log.cc:1079] T 65d6fb310f214215b638e04ecd3296f7 P 55d61543782041b8b54cd0059dfe8a10: Deleting log segment in path: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520401731-7292-0/minicluster-data/ts-0-root/wals/65d6fb310f214215b638e04ecd3296f7/wal-000000001 (ops 1-6)
I20260812 06:18:41.054667  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: LogGCOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:18:41.055225  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7): perf score=2.188937
I20260812 06:18:41.076576  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.021s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7088,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:41.077167  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling MajorDeltaCompactionOp(65d6fb310f214215b638e04ecd3296f7): perf score=1.000000
I20260812 06:18:41.218951  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: MajorDeltaCompactionOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.142s	user 0.105s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":502,"lbm_read_time_us":9537,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27825,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"thread_start_us":341,"threads_started":5,"update_count":2000}
I20260812 06:18:41.219565  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling UndoDeltaBlockGCOp(65d6fb310f214215b638e04ecd3296f7): 12308958 bytes on disk
I20260812 06:18:41.220368  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: UndoDeltaBlockGCOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":87,"lbm_reads_lt_1ms":4}
I20260812 06:18:41.220954  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7): perf score=10.126437
I20260812 06:18:41.270133  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.049s	user 0.024s	sys 0.009s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15520,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:41.270766  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7): perf score=2.188937
I20260812 06:18:41.282980  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.012s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4271,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:41.283686  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling MajorDeltaCompactionOp(65d6fb310f214215b638e04ecd3296f7): perf score=1.000000
I20260812 06:18:41.445230  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: MajorDeltaCompactionOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.161s	user 0.124s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":2731,"lbm_read_time_us":11453,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29414,"lbm_writes_lt_1ms":443,"mutex_wait_us":832,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":24960,"update_count":2000}
I20260812 06:18:41.446614  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7): perf score=10.126437
I20260812 06:18:41.512914  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.066s	user 0.034s	sys 0.022s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":26954,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:41.513546  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7): perf score=2.188937
I20260812 06:18:41.525998  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4227,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:41.526644  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling MajorDeltaCompactionOp(65d6fb310f214215b638e04ecd3296f7): perf score=1.000000
I20260812 06:18:41.678501  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: MajorDeltaCompactionOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.152s	user 0.122s	sys 0.029s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":582,"lbm_read_time_us":11037,"lbm_reads_lt_1ms":472,"lbm_write_time_us":30927,"lbm_writes_lt_1ms":443,"mutex_wait_us":201,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:41.679355  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7): perf score=10.126437
I20260812 06:18:41.742726  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.063s	user 0.032s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18110,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:41.743418  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7): perf score=2.188937
I20260812 06:18:41.756824  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.013s	user 0.008s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5400,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:41.757349  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling MajorDeltaCompactionOp(65d6fb310f214215b638e04ecd3296f7): perf score=1.000000
I20260812 06:18:41.941454  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: MajorDeltaCompactionOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.184s	user 0.120s	sys 0.064s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":258,"lbm_read_time_us":12194,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27650,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:41.942135  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7): perf score=10.126437
I20260812 06:18:41.996961  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.054s	user 0.023s	sys 0.021s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":19467,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:41.997666  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7): perf score=2.188937
I20260812 06:18:42.010762  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.013s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4738,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:42.011519  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling MajorDeltaCompactionOp(65d6fb310f214215b638e04ecd3296f7): perf score=1.000000
I20260812 06:18:42.153893  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: MajorDeltaCompactionOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.142s	user 0.106s	sys 0.035s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631314,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1596,"lbm_read_time_us":8471,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28575,"lbm_writes_lt_1ms":443,"mutex_wait_us":60,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":29824,"update_count":2000}
I20260812 06:18:42.156589  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7): perf score=10.126437
I20260812 06:18:42.209455  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.052s	user 0.017s	sys 0.020s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17439,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:42.209959  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7): perf score=2.188937
I20260812 06:18:42.223295  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.013s	user 0.005s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4978,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:42.223912  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling MajorDeltaCompactionOp(65d6fb310f214215b638e04ecd3296f7): perf score=1.000000
I20260812 06:18:42.383363  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: MajorDeltaCompactionOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.159s	user 0.139s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":365,"lbm_read_time_us":9259,"lbm_reads_lt_1ms":472,"lbm_write_time_us":31725,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":31,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":39424,"update_count":2000}
I20260812 06:18:42.384280  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7): perf score=10.126437
I20260812 06:18:42.442231  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.058s	user 0.040s	sys 0.014s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":22967,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:42.443060  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7): perf score=2.188937
I20260812 06:18:42.463260  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.020s	user 0.011s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":8554,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:42.464623  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling FlushMRSOp(65d6fb310f214215b638e04ecd3296f7): perf score=1.000000
I20260812 06:18:42.506511  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: FlushMRSOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.042s	user 0.030s	sys 0.003s Metrics: {"bytes_written":1152509,"cfile_init":1,"dirs.queue_time_us":96,"dirs.run_cpu_time_us":320,"dirs.run_wall_time_us":2129,"drs_written":1,"lbm_read_time_us":45,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1544,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:42.508010  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling MajorDeltaCompactionOp(65d6fb310f214215b638e04ecd3296f7): perf score=1.000000
I20260812 06:18:42.670212  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: MajorDeltaCompactionOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.162s	user 0.116s	sys 0.044s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":534,"lbm_read_time_us":9414,"lbm_reads_lt_1ms":464,"lbm_write_time_us":31068,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":1,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:18:42.670939  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling LogGCOp(65d6fb310f214215b638e04ecd3296f7): free 123804179 bytes of WAL
I20260812 06:18:42.671209  7413 log_reader.cc:385] T 65d6fb310f214215b638e04ecd3296f7: removed 12 log segments from log reader
I20260812 06:18:42.671283  7413 log.cc:1079] T 65d6fb310f214215b638e04ecd3296f7 P 55d61543782041b8b54cd0059dfe8a10: Deleting log segment in path: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520401731-7292-0/minicluster-data/ts-0-root/wals/65d6fb310f214215b638e04ecd3296f7/wal-000000002 (ops 7-11)
I20260812 06:18:42.671371  7413 log.cc:1079] T 65d6fb310f214215b638e04ecd3296f7 P 55d61543782041b8b54cd0059dfe8a10: Deleting log segment in path: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520401731-7292-0/minicluster-data/ts-0-root/wals/65d6fb310f214215b638e04ecd3296f7/wal-000000003 (ops 12-16)
I20260812 06:18:42.671417  7413 log.cc:1079] T 65d6fb310f214215b638e04ecd3296f7 P 55d61543782041b8b54cd0059dfe8a10: Deleting log segment in path: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520401731-7292-0/minicluster-data/ts-0-root/wals/65d6fb310f214215b638e04ecd3296f7/wal-000000004 (ops 17-21)
I20260812 06:18:42.671452  7413 log.cc:1079] T 65d6fb310f214215b638e04ecd3296f7 P 55d61543782041b8b54cd0059dfe8a10: Deleting log segment in path: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520401731-7292-0/minicluster-data/ts-0-root/wals/65d6fb310f214215b638e04ecd3296f7/wal-000000005 (ops 22-26)
I20260812 06:18:42.671491  7413 log.cc:1079] T 65d6fb310f214215b638e04ecd3296f7 P 55d61543782041b8b54cd0059dfe8a10: Deleting log segment in path: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520401731-7292-0/minicluster-data/ts-0-root/wals/65d6fb310f214215b638e04ecd3296f7/wal-000000006 (ops 27-31)
I20260812 06:18:42.671566  7413 log.cc:1079] T 65d6fb310f214215b638e04ecd3296f7 P 55d61543782041b8b54cd0059dfe8a10: Deleting log segment in path: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520401731-7292-0/minicluster-data/ts-0-root/wals/65d6fb310f214215b638e04ecd3296f7/wal-000000007 (ops 32-36)
I20260812 06:18:42.671643  7413 log.cc:1079] T 65d6fb310f214215b638e04ecd3296f7 P 55d61543782041b8b54cd0059dfe8a10: Deleting log segment in path: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520401731-7292-0/minicluster-data/ts-0-root/wals/65d6fb310f214215b638e04ecd3296f7/wal-000000008 (ops 37-41)
I20260812 06:18:42.671696  7413 log.cc:1079] T 65d6fb310f214215b638e04ecd3296f7 P 55d61543782041b8b54cd0059dfe8a10: Deleting log segment in path: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520401731-7292-0/minicluster-data/ts-0-root/wals/65d6fb310f214215b638e04ecd3296f7/wal-000000009 (ops 42-46)
I20260812 06:18:42.671767  7413 log.cc:1079] T 65d6fb310f214215b638e04ecd3296f7 P 55d61543782041b8b54cd0059dfe8a10: Deleting log segment in path: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520401731-7292-0/minicluster-data/ts-0-root/wals/65d6fb310f214215b638e04ecd3296f7/wal-000000010 (ops 47-50)
I20260812 06:18:42.671823  7413 log.cc:1079] T 65d6fb310f214215b638e04ecd3296f7 P 55d61543782041b8b54cd0059dfe8a10: Deleting log segment in path: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520401731-7292-0/minicluster-data/ts-0-root/wals/65d6fb310f214215b638e04ecd3296f7/wal-000000011 (ops 51-55)
I20260812 06:18:42.671895  7413 log.cc:1079] T 65d6fb310f214215b638e04ecd3296f7 P 55d61543782041b8b54cd0059dfe8a10: Deleting log segment in path: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520401731-7292-0/minicluster-data/ts-0-root/wals/65d6fb310f214215b638e04ecd3296f7/wal-000000012 (ops 56-60)
I20260812 06:18:42.671977  7413 log.cc:1079] T 65d6fb310f214215b638e04ecd3296f7 P 55d61543782041b8b54cd0059dfe8a10: Deleting log segment in path: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520401731-7292-0/minicluster-data/ts-0-root/wals/65d6fb310f214215b638e04ecd3296f7/wal-000000013 (ops 61-64)
I20260812 06:18:42.715641  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: LogGCOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.044s	user 0.000s	sys 0.043s Metrics: {}
I20260812 06:18:42.716228  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7): perf score=14.095187
I20260812 06:18:42.772758  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.056s	user 0.034s	sys 0.020s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":26752,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:42.773424  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7): perf score=2.188937
I20260812 06:18:42.793536  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.020s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6500,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:42.794358  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling UndoDeltaBlockGCOp(65d6fb310f214215b638e04ecd3296f7): 447 bytes on disk
I20260812 06:18:42.795256  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: UndoDeltaBlockGCOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":262,"lbm_reads_lt_1ms":4}
I20260812 06:18:42.795761  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling MajorDeltaCompactionOp(65d6fb310f214215b638e04ecd3296f7): perf score=1.000000
I20260812 06:18:43.036840  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: MajorDeltaCompactionOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.241s	user 0.186s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":535,"lbm_read_time_us":16108,"lbm_reads_lt_1ms":564,"lbm_write_time_us":41204,"lbm_writes_lt_1ms":543,"mutex_wait_us":48,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2500}
I20260812 06:18:43.037827  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7): perf score=14.095187
I20260812 06:18:43.119058  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.081s	user 0.044s	sys 0.036s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":34388,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:43.119696  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7): perf score=2.188937
I20260812 06:18:43.155380  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.036s	user 0.016s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":7818,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.155882  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7): perf score=2.188937
I20260812 06:18:43.172417  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.016s	user 0.005s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6365,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.173206  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling MajorDeltaCompactionOp(65d6fb310f214215b638e04ecd3296f7): perf score=1.000000
I20260812 06:18:43.459511  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: MajorDeltaCompactionOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.286s	user 0.198s	sys 0.080s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28836256,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":273,"lbm_read_time_us":15385,"lbm_reads_lt_1ms":673,"lbm_write_time_us":53102,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":641,"mutex_wait_us":44,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":8960,"update_count":3000}
I20260812 06:18:43.460932  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7): perf score=14.095187
I20260812 06:18:43.531714  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.070s	user 0.026s	sys 0.043s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":36285,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":400,"reinsert_count":0,"update_count":2000}
I20260812 06:18:43.532370  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7): perf score=2.188937
I20260812 06:18:43.569213  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.037s	user 0.009s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":9237,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.569808  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling MajorDeltaCompactionOp(65d6fb310f214215b638e04ecd3296f7): perf score=1.000000
I20260812 06:18:43.797338  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: MajorDeltaCompactionOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.227s	user 0.135s	sys 0.092s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733722,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":985,"lbm_read_time_us":16427,"lbm_reads_lt_1ms":564,"lbm_write_time_us":39452,"lbm_writes_lt_1ms":543,"mutex_wait_us":351,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12032,"update_count":2500}
I20260812 06:18:43.798529  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7): perf score=14.095187
I20260812 06:18:43.858884  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.060s	user 0.032s	sys 0.028s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":27903,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:43.859550  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7): perf score=2.188937
I20260812 06:18:43.876071  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.016s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6523,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.877009  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling MajorDeltaCompactionOp(65d6fb310f214215b638e04ecd3296f7): perf score=1.000000
I20260812 06:18:44.136958  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: MajorDeltaCompactionOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.260s	user 0.194s	sys 0.049s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":935,"lbm_read_time_us":21802,"lbm_reads_lt_1ms":572,"lbm_write_time_us":42054,"lbm_writes_lt_1ms":543,"mutex_wait_us":378,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:44.137809  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7): perf score=14.095187
I20260812 06:18:44.204046  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.066s	user 0.029s	sys 0.035s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":29998,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:44.204630  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7): perf score=2.188937
I20260812 06:18:44.222594  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.018s	user 0.009s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6351,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.223642  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling MajorDeltaCompactionOp(65d6fb310f214215b638e04ecd3296f7): perf score=1.000000
I20260812 06:18:44.386304  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: MajorDeltaCompactionOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.162s	user 0.117s	sys 0.045s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733725,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":257,"lbm_read_time_us":14977,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32493,"lbm_writes_lt_1ms":543,"mutex_wait_us":77,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8576,"update_count":2500}
I20260812 06:18:44.387130  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7): perf score=10.126437
I20260812 06:18:44.426771  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.039s	user 0.012s	sys 0.027s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17792,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:44.427470  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7): perf score=3.181125
I20260812 06:18:44.451581  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.023s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":6415,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:44.452090  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7): perf score=2.188937
I20260812 06:18:44.463178  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4192,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:44.463763  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling FlushMRSOp(65d6fb310f214215b638e04ecd3296f7): perf score=1.000000
I20260812 06:18:44.498502  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: FlushMRSOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.035s	user 0.033s	sys 0.000s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":66,"dirs.run_cpu_time_us":237,"dirs.run_wall_time_us":1337,"drs_written":1,"lbm_read_time_us":75,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1862,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:44.499341  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling LogGCOp(65d6fb310f214215b638e04ecd3296f7): free 121006434 bytes of WAL
I20260812 06:18:44.499579  7413 log_reader.cc:385] T 65d6fb310f214215b638e04ecd3296f7: removed 12 log segments from log reader
I20260812 06:18:44.499622  7413 log.cc:1079] T 65d6fb310f214215b638e04ecd3296f7 P 55d61543782041b8b54cd0059dfe8a10: Deleting log segment in path: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520401731-7292-0/minicluster-data/ts-0-root/wals/65d6fb310f214215b638e04ecd3296f7/wal-000000014 (ops 65-69)
I20260812 06:18:44.499651  7413 log.cc:1079] T 65d6fb310f214215b638e04ecd3296f7 P 55d61543782041b8b54cd0059dfe8a10: Deleting log segment in path: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520401731-7292-0/minicluster-data/ts-0-root/wals/65d6fb310f214215b638e04ecd3296f7/wal-000000015 (ops 70-74)
I20260812 06:18:44.499711  7413 log.cc:1079] T 65d6fb310f214215b638e04ecd3296f7 P 55d61543782041b8b54cd0059dfe8a10: Deleting log segment in path: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520401731-7292-0/minicluster-data/ts-0-root/wals/65d6fb310f214215b638e04ecd3296f7/wal-000000016 (ops 75-79)
I20260812 06:18:44.499742  7413 log.cc:1079] T 65d6fb310f214215b638e04ecd3296f7 P 55d61543782041b8b54cd0059dfe8a10: Deleting log segment in path: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520401731-7292-0/minicluster-data/ts-0-root/wals/65d6fb310f214215b638e04ecd3296f7/wal-000000017 (ops 80-84)
I20260812 06:18:44.499778  7413 log.cc:1079] T 65d6fb310f214215b638e04ecd3296f7 P 55d61543782041b8b54cd0059dfe8a10: Deleting log segment in path: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520401731-7292-0/minicluster-data/ts-0-root/wals/65d6fb310f214215b638e04ecd3296f7/wal-000000018 (ops 85-89)
I20260812 06:18:44.499836  7413 log.cc:1079] T 65d6fb310f214215b638e04ecd3296f7 P 55d61543782041b8b54cd0059dfe8a10: Deleting log segment in path: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520401731-7292-0/minicluster-data/ts-0-root/wals/65d6fb310f214215b638e04ecd3296f7/wal-000000019 (ops 90-94)
I20260812 06:18:44.499882  7413 log.cc:1079] T 65d6fb310f214215b638e04ecd3296f7 P 55d61543782041b8b54cd0059dfe8a10: Deleting log segment in path: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520401731-7292-0/minicluster-data/ts-0-root/wals/65d6fb310f214215b638e04ecd3296f7/wal-000000020 (ops 95-99)
I20260812 06:18:44.499924  7413 log.cc:1079] T 65d6fb310f214215b638e04ecd3296f7 P 55d61543782041b8b54cd0059dfe8a10: Deleting log segment in path: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520401731-7292-0/minicluster-data/ts-0-root/wals/65d6fb310f214215b638e04ecd3296f7/wal-000000021 (ops 100-104)
I20260812 06:18:44.499962  7413 log.cc:1079] T 65d6fb310f214215b638e04ecd3296f7 P 55d61543782041b8b54cd0059dfe8a10: Deleting log segment in path: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520401731-7292-0/minicluster-data/ts-0-root/wals/65d6fb310f214215b638e04ecd3296f7/wal-000000022 (ops 105-108)
I20260812 06:18:44.500000  7413 log.cc:1079] T 65d6fb310f214215b638e04ecd3296f7 P 55d61543782041b8b54cd0059dfe8a10: Deleting log segment in path: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520401731-7292-0/minicluster-data/ts-0-root/wals/65d6fb310f214215b638e04ecd3296f7/wal-000000023 (ops 109-113)
I20260812 06:18:44.500039  7413 log.cc:1079] T 65d6fb310f214215b638e04ecd3296f7 P 55d61543782041b8b54cd0059dfe8a10: Deleting log segment in path: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520401731-7292-0/minicluster-data/ts-0-root/wals/65d6fb310f214215b638e04ecd3296f7/wal-000000024 (ops 114-118)
I20260812 06:18:44.500077  7413 log.cc:1079] T 65d6fb310f214215b638e04ecd3296f7 P 55d61543782041b8b54cd0059dfe8a10: Deleting log segment in path: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520401731-7292-0/minicluster-data/ts-0-root/wals/65d6fb310f214215b638e04ecd3296f7/wal-000000025 (ops 119-123)
I20260812 06:18:44.528101  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: LogGCOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.029s	user 0.003s	sys 0.024s Metrics: {}
I20260812 06:18:44.528656  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7): perf score=3.181125
I20260812 06:18:44.547851  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.019s	user 0.012s	sys 0.005s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":7424,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:44.548408  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling LogGCOp(65d6fb310f214215b638e04ecd3296f7): free 12017932 bytes of WAL
I20260812 06:18:44.548691  7413 log_reader.cc:385] T 65d6fb310f214215b638e04ecd3296f7: removed 1 log segments from log reader
I20260812 06:18:44.548753  7413 log.cc:1079] T 65d6fb310f214215b638e04ecd3296f7 P 55d61543782041b8b54cd0059dfe8a10: Deleting log segment in path: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520401731-7292-0/minicluster-data/ts-0-root/wals/65d6fb310f214215b638e04ecd3296f7/wal-000000026 (ops 124-128)
I20260812 06:18:44.551927  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: LogGCOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.003s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:18:44.552393  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7): perf score=2.188937
I20260812 06:18:44.575989  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.023s	user 0.006s	sys 0.016s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5115,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:44.576655  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling MajorDeltaCompactionOp(65d6fb310f214215b638e04ecd3296f7): perf score=1.000000
I20260812 06:18:44.802498  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: MajorDeltaCompactionOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.226s	user 0.137s	sys 0.088s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32938884,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":905,"lbm_read_time_us":15641,"lbm_reads_lt_1ms":775,"lbm_write_time_us":40151,"lbm_writes_lt_1ms":743,"mutex_wait_us":27,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":7552,"thread_start_us":88,"threads_started":1,"update_count":3500}
I20260812 06:18:44.803304  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling UndoDeltaBlockGCOp(65d6fb310f214215b638e04ecd3296f7): 483 bytes on disk
I20260812 06:18:44.804890  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: UndoDeltaBlockGCOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":73,"lbm_reads_lt_1ms":4}
I20260812 06:18:44.805804  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7): perf score=14.095187
I20260812 06:18:44.865808  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.060s	user 0.032s	sys 0.025s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22427,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:44.866459  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7): perf score=2.188937
I20260812 06:18:44.881403  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.015s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5579,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.883471  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling MajorDeltaCompactionOp(65d6fb310f214215b638e04ecd3296f7): perf score=1.000000
I20260812 06:18:45.075546  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: MajorDeltaCompactionOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.192s	user 0.124s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1147,"lbm_read_time_us":12880,"lbm_reads_lt_1ms":564,"lbm_write_time_us":31721,"lbm_writes_lt_1ms":543,"mutex_wait_us":360,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4352,"update_count":2500}
I20260812 06:18:45.076227  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7): perf score=14.095187
I20260812 06:18:45.144178  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.068s	user 0.036s	sys 0.023s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":22219,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:45.144776  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7): perf score=2.188937
I20260812 06:18:45.156170  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4349,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.156888  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling MajorDeltaCompactionOp(65d6fb310f214215b638e04ecd3296f7): perf score=1.000000
I20260812 06:18:45.339013  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: MajorDeltaCompactionOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.182s	user 0.113s	sys 0.064s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733726,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":773,"lbm_read_time_us":13122,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30784,"lbm_writes_lt_1ms":543,"mutex_wait_us":293,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:45.339898  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7): perf score=10.126437
I20260812 06:18:45.378789  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.039s	user 0.025s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16647,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:45.379976  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7): perf score=2.188937
I20260812 06:18:45.398129  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.018s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6573,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.398854  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling MajorDeltaCompactionOp(65d6fb310f214215b638e04ecd3296f7): perf score=1.000000
I20260812 06:18:45.545964  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: MajorDeltaCompactionOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.147s	user 0.105s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1108,"lbm_read_time_us":8016,"lbm_reads_lt_1ms":464,"lbm_write_time_us":28722,"lbm_writes_lt_1ms":443,"mutex_wait_us":94,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:45.549314  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7): perf score=10.126437
I20260812 06:18:45.588446  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.039s	user 0.021s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17508,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:45.589073  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7): perf score=2.188937
I20260812 06:18:45.602298  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.013s	user 0.004s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5191,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.602942  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling MajorDeltaCompactionOp(65d6fb310f214215b638e04ecd3296f7): perf score=1.000000
I20260812 06:18:45.750039  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: MajorDeltaCompactionOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.147s	user 0.109s	sys 0.037s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":903,"lbm_read_time_us":10622,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26739,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:18:45.750860  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7): perf score=10.126437
I20260812 06:18:45.796128  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.045s	user 0.026s	sys 0.016s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":19197,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:45.796677  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7): perf score=2.188937
I20260812 06:18:45.807960  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4181,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.808859  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling MajorDeltaCompactionOp(65d6fb310f214215b638e04ecd3296f7): perf score=1.000000
I20260812 06:18:45.942906  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: MajorDeltaCompactionOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.134s	user 0.099s	sys 0.034s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":232,"lbm_read_time_us":9552,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23536,"lbm_writes_lt_1ms":443,"mutex_wait_us":26,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13440,"update_count":2000}
I20260812 06:18:45.945298  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7): perf score=10.126437
I20260812 06:18:45.999006  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.052s	user 0.023s	sys 0.028s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18376,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:45.999697  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7): perf score=2.188937
I20260812 06:18:46.011983  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.012s	user 0.010s	sys 0.001s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4540,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:46.012579  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling FlushMRSOp(65d6fb310f214215b638e04ecd3296f7): perf score=1.000000
I20260812 06:18:46.053154  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: FlushMRSOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.040s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":71,"dirs.run_cpu_time_us":263,"dirs.run_wall_time_us":1651,"drs_written":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1809,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:46.053901  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling LogGCOp(65d6fb310f214215b638e04ecd3296f7): free 112239552 bytes of WAL
I20260812 06:18:46.054193  7413 log_reader.cc:385] T 65d6fb310f214215b638e04ecd3296f7: removed 11 log segments from log reader
I20260812 06:18:46.054239  7413 log.cc:1079] T 65d6fb310f214215b638e04ecd3296f7 P 55d61543782041b8b54cd0059dfe8a10: Deleting log segment in path: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520401731-7292-0/minicluster-data/ts-0-root/wals/65d6fb310f214215b638e04ecd3296f7/wal-000000027 (ops 129-133)
I20260812 06:18:46.054270  7413 log.cc:1079] T 65d6fb310f214215b638e04ecd3296f7 P 55d61543782041b8b54cd0059dfe8a10: Deleting log segment in path: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520401731-7292-0/minicluster-data/ts-0-root/wals/65d6fb310f214215b638e04ecd3296f7/wal-000000028 (ops 134-138)
I20260812 06:18:46.054333  7413 log.cc:1079] T 65d6fb310f214215b638e04ecd3296f7 P 55d61543782041b8b54cd0059dfe8a10: Deleting log segment in path: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520401731-7292-0/minicluster-data/ts-0-root/wals/65d6fb310f214215b638e04ecd3296f7/wal-000000029 (ops 139-143)
I20260812 06:18:46.054383  7413 log.cc:1079] T 65d6fb310f214215b638e04ecd3296f7 P 55d61543782041b8b54cd0059dfe8a10: Deleting log segment in path: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520401731-7292-0/minicluster-data/ts-0-root/wals/65d6fb310f214215b638e04ecd3296f7/wal-000000030 (ops 144-148)
I20260812 06:18:46.054433  7413 log.cc:1079] T 65d6fb310f214215b638e04ecd3296f7 P 55d61543782041b8b54cd0059dfe8a10: Deleting log segment in path: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520401731-7292-0/minicluster-data/ts-0-root/wals/65d6fb310f214215b638e04ecd3296f7/wal-000000031 (ops 149-153)
I20260812 06:18:46.054497  7413 log.cc:1079] T 65d6fb310f214215b638e04ecd3296f7 P 55d61543782041b8b54cd0059dfe8a10: Deleting log segment in path: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520401731-7292-0/minicluster-data/ts-0-root/wals/65d6fb310f214215b638e04ecd3296f7/wal-000000032 (ops 154-158)
I20260812 06:18:46.054548  7413 log.cc:1079] T 65d6fb310f214215b638e04ecd3296f7 P 55d61543782041b8b54cd0059dfe8a10: Deleting log segment in path: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520401731-7292-0/minicluster-data/ts-0-root/wals/65d6fb310f214215b638e04ecd3296f7/wal-000000033 (ops 159-163)
I20260812 06:18:46.054587  7413 log.cc:1079] T 65d6fb310f214215b638e04ecd3296f7 P 55d61543782041b8b54cd0059dfe8a10: Deleting log segment in path: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520401731-7292-0/minicluster-data/ts-0-root/wals/65d6fb310f214215b638e04ecd3296f7/wal-000000034 (ops 164-168)
I20260812 06:18:46.054628  7413 log.cc:1079] T 65d6fb310f214215b638e04ecd3296f7 P 55d61543782041b8b54cd0059dfe8a10: Deleting log segment in path: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520401731-7292-0/minicluster-data/ts-0-root/wals/65d6fb310f214215b638e04ecd3296f7/wal-000000035 (ops 169-173)
I20260812 06:18:46.054695  7413 log.cc:1079] T 65d6fb310f214215b638e04ecd3296f7 P 55d61543782041b8b54cd0059dfe8a10: Deleting log segment in path: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520401731-7292-0/minicluster-data/ts-0-root/wals/65d6fb310f214215b638e04ecd3296f7/wal-000000036 (ops 174-178)
I20260812 06:18:46.054737  7413 log.cc:1079] T 65d6fb310f214215b638e04ecd3296f7 P 55d61543782041b8b54cd0059dfe8a10: Deleting log segment in path: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520401731-7292-0/minicluster-data/ts-0-root/wals/65d6fb310f214215b638e04ecd3296f7/wal-000000037 (ops 179-182)
I20260812 06:18:46.079892  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: LogGCOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.026s	user 0.003s	sys 0.022s Metrics: {}
I20260812 06:18:46.080557  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling UndoDeltaBlockGCOp(65d6fb310f214215b638e04ecd3296f7): 447 bytes on disk
I20260812 06:18:46.081224  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: UndoDeltaBlockGCOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":65,"lbm_reads_lt_1ms":4}
I20260812 06:18:46.081849  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7): perf score=3.181125
I20260812 06:18:46.099869  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.018s	user 0.010s	sys 0.001s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4571,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:46.100446  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7): perf score=2.188937
I20260812 06:18:46.114787  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.014s	user 0.014s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5224,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:46.115484  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling MajorDeltaCompactionOp(65d6fb310f214215b638e04ecd3296f7): perf score=1.000000
I20260812 06:18:46.331498  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: MajorDeltaCompactionOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.216s	user 0.144s	sys 0.071s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836363,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1395,"lbm_read_time_us":14458,"lbm_reads_lt_1ms":674,"lbm_write_time_us":36221,"lbm_writes_lt_1ms":643,"mutex_wait_us":430,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":159488,"thread_start_us":85,"threads_started":1,"update_count":3000}
I20260812 06:18:46.332301  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7): perf score=14.095187
I20260812 06:18:46.392870  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.060s	user 0.035s	sys 0.021s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":25504,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:46.393478  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling MajorDeltaCompactionOp(65d6fb310f214215b638e04ecd3296f7): perf score=1.000000
I20260812 06:18:46.552814  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: MajorDeltaCompactionOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.159s	user 0.112s	sys 0.045s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20631191,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":168,"lbm_read_time_us":9653,"lbm_reads_lt_1ms":463,"lbm_write_time_us":28956,"lbm_writes_lt_1ms":443,"mutex_wait_us":2,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":54400,"update_count":2000}
I20260812 06:18:46.553653  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7): perf score=10.126437
I20260812 06:18:46.573575  7292 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.851s	user 2.107s	sys 0.175s
I20260812 06:18:46.591102  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.037s	user 0.033s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16371,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:46.591583  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7): perf score=2.188937
I20260812 06:18:46.603272  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: FlushDeltaMemStoresOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4312,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:46.603850  7478 maintenance_manager.cc:419] P 55d61543782041b8b54cd0059dfe8a10: Scheduling MajorDeltaCompactionOp(65d6fb310f214215b638e04ecd3296f7): perf score=1.000000
I20260812 06:18:46.607453  7292 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.033s	user 0.004s	sys 0.000s
I20260812 06:18:46.608130  7292 tablet_server.cc:179] TabletServer@127.7.31.1:0 shutting down...
I20260812 06:18:46.715984  7413 maintenance_manager.cc:643] P 55d61543782041b8b54cd0059dfe8a10: MajorDeltaCompactionOp(65d6fb310f214215b638e04ecd3296f7) complete. Timing: real 0.112s	user 0.095s	sys 0.015s Metrics: {"cfile_cache_hit":30,"cfile_cache_hit_bytes":4221425,"cfile_cache_miss":402,"cfile_cache_miss_bytes":16409887,"cfile_init":4,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":743,"lbm_read_time_us":7508,"lbm_reads_lt_1ms":418,"lbm_write_time_us":20939,"lbm_writes_lt_1ms":443,"mutex_wait_us":288,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11008,"update_count":2000}
I20260812 06:18:46.716831  7292 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:46.719173  7292 tablet_replica.cc:333] T 65d6fb310f214215b638e04ecd3296f7 P 55d61543782041b8b54cd0059dfe8a10: stopping tablet replica
I20260812 06:18:46.719483  7292 raft_consensus.cc:2243] T 65d6fb310f214215b638e04ecd3296f7 P 55d61543782041b8b54cd0059dfe8a10 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:46.719744  7292 raft_consensus.cc:2272] T 65d6fb310f214215b638e04ecd3296f7 P 55d61543782041b8b54cd0059dfe8a10 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:46.725050  7292 tablet_server.cc:196] TabletServer@127.7.31.1:0 shutdown complete.
I20260812 06:18:46.756494  7292 master.cc:562] Master@127.7.31.62:34565 shutting down...
I20260812 06:18:46.760845  7292 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 5fed1f6818ca4439957e8c0e26b87469 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:46.761091  7292 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 5fed1f6818ca4439957e8c0e26b87469 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:46.761191  7292 tablet_replica.cc:333] T 00000000000000000000000000000000 P 5fed1f6818ca4439957e8c0e26b87469: stopping tablet replica
I20260812 06:18:46.773998  7292 master.cc:584] Master@127.7.31.62:34565 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (6457 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:46.869900  7292 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.7.31.62:36979
I20260812 06:18:46.870276  7292 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:46.872462  7518 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:46.872488  7515 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:46.872601  7292 server_base.cc:1061] running on GCE node
W20260812 06:18:46.872608  7516 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:46.872939  7292 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:46.872983  7292 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:46.872998  7292 hybrid_clock.cc:648] HybridClock initialized: now 1786515526872998 us; error 0 us; skew 500 ppm
I20260812 06:18:46.873813  7292 webserver.cc:533] Webserver started at http://127.7.31.62:36895/ using document root <none> and password file <none>
I20260812 06:18:46.874014  7292 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:46.874136  7292 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:46.874274  7292 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:46.874752  7292 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520401731-7292-0/minicluster-data/master-0-root/instance:
uuid: "55f3814e9ddd41499a2f66997872581f"
format_stamp: "Formatted at 2026-08-12 06:18:46 on dist-test-slave-8tdl"
I20260812 06:18:46.876361  7292 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:46.877331  7523 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:46.877620  7292 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:46.877718  7292 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520401731-7292-0/minicluster-data/master-0-root
uuid: "55f3814e9ddd41499a2f66997872581f"
format_stamp: "Formatted at 2026-08-12 06:18:46 on dist-test-slave-8tdl"
I20260812 06:18:46.877810  7292 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520401731-7292-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520401731-7292-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520401731-7292-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:46.885349  7292 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:46.885795  7292 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:46.890445  7292 rpc_server.cc:307] RPC server started. Bound to: 127.7.31.62:36979
I20260812 06:18:46.893749  7582 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.7.31.62:36979 every 8 connection(s)
I20260812 06:18:46.904531  7583 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:46.906741  7583 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 55f3814e9ddd41499a2f66997872581f: Bootstrap starting.
I20260812 06:18:46.907641  7583 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 55f3814e9ddd41499a2f66997872581f: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:46.908812  7583 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 55f3814e9ddd41499a2f66997872581f: No bootstrap required, opened a new log
I20260812 06:18:46.909267  7583 raft_consensus.cc:359] T 00000000000000000000000000000000 P 55f3814e9ddd41499a2f66997872581f [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "55f3814e9ddd41499a2f66997872581f" member_type: VOTER }
I20260812 06:18:46.909389  7583 raft_consensus.cc:385] T 00000000000000000000000000000000 P 55f3814e9ddd41499a2f66997872581f [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:46.909442  7583 raft_consensus.cc:740] T 00000000000000000000000000000000 P 55f3814e9ddd41499a2f66997872581f [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 55f3814e9ddd41499a2f66997872581f, State: Initialized, Role: FOLLOWER
I20260812 06:18:46.909626  7583 consensus_queue.cc:260] T 00000000000000000000000000000000 P 55f3814e9ddd41499a2f66997872581f [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: "55f3814e9ddd41499a2f66997872581f" member_type: VOTER }
I20260812 06:18:46.909726  7583 raft_consensus.cc:399] T 00000000000000000000000000000000 P 55f3814e9ddd41499a2f66997872581f [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:46.909775  7583 raft_consensus.cc:493] T 00000000000000000000000000000000 P 55f3814e9ddd41499a2f66997872581f [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:46.909863  7583 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 55f3814e9ddd41499a2f66997872581f [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:46.910668  7583 raft_consensus.cc:515] T 00000000000000000000000000000000 P 55f3814e9ddd41499a2f66997872581f [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "55f3814e9ddd41499a2f66997872581f" member_type: VOTER }
I20260812 06:18:46.910858  7583 leader_election.cc:304] T 00000000000000000000000000000000 P 55f3814e9ddd41499a2f66997872581f [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: 55f3814e9ddd41499a2f66997872581f; no voters: 
I20260812 06:18:46.911084  7583 leader_election.cc:290] T 00000000000000000000000000000000 P 55f3814e9ddd41499a2f66997872581f [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:46.911263  7587 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 55f3814e9ddd41499a2f66997872581f [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:46.911535  7587 raft_consensus.cc:697] T 00000000000000000000000000000000 P 55f3814e9ddd41499a2f66997872581f [term 1 LEADER]: Becoming Leader. State: Replica: 55f3814e9ddd41499a2f66997872581f, State: Running, Role: LEADER
I20260812 06:18:46.911696  7583 sys_catalog.cc:565] T 00000000000000000000000000000000 P 55f3814e9ddd41499a2f66997872581f [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:46.911679  7587 consensus_queue.cc:237] T 00000000000000000000000000000000 P 55f3814e9ddd41499a2f66997872581f [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: "55f3814e9ddd41499a2f66997872581f" member_type: VOTER }
I20260812 06:18:46.912232  7589 sys_catalog.cc:455] T 00000000000000000000000000000000 P 55f3814e9ddd41499a2f66997872581f [sys.catalog]: SysCatalogTable state changed. Reason: New leader 55f3814e9ddd41499a2f66997872581f. Latest consensus state: current_term: 1 leader_uuid: "55f3814e9ddd41499a2f66997872581f" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "55f3814e9ddd41499a2f66997872581f" member_type: VOTER } }
I20260812 06:18:46.912216  7588 sys_catalog.cc:455] T 00000000000000000000000000000000 P 55f3814e9ddd41499a2f66997872581f [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "55f3814e9ddd41499a2f66997872581f" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "55f3814e9ddd41499a2f66997872581f" member_type: VOTER } }
I20260812 06:18:46.912402  7589 sys_catalog.cc:458] T 00000000000000000000000000000000 P 55f3814e9ddd41499a2f66997872581f [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:46.912477  7588 sys_catalog.cc:458] T 00000000000000000000000000000000 P 55f3814e9ddd41499a2f66997872581f [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:46.912732  7595 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:46.913520  7595 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:46.913827  7292 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:46.915668  7595 catalog_manager.cc:1383] Generated new cluster ID: cb249579b32e4805b5b8dc5dd28d768a
I20260812 06:18:46.915740  7595 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:46.938742  7595 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:46.939406  7595 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:46.952467  7595 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 55f3814e9ddd41499a2f66997872581f: Generated new TSK 0
I20260812 06:18:46.952682  7595 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:46.979079  7292 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:46.981371  7607 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:46.981428  7610 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:46.981428  7608 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:46.981494  7292 server_base.cc:1061] running on GCE node
I20260812 06:18:46.981765  7292 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:46.981804  7292 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:46.981820  7292 hybrid_clock.cc:648] HybridClock initialized: now 1786515526981820 us; error 0 us; skew 500 ppm
I20260812 06:18:46.982811  7292 webserver.cc:533] Webserver started at http://127.7.31.1:42037/ using document root <none> and password file <none>
I20260812 06:18:46.983062  7292 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:46.983114  7292 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:46.983176  7292 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:46.983554  7292 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520401731-7292-0/minicluster-data/ts-0-root/instance:
uuid: "c4bd67ff39e14d379199b306453d78ca"
format_stamp: "Formatted at 2026-08-12 06:18:46 on dist-test-slave-8tdl"
I20260812 06:18:46.985152  7292 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:18:46.986285  7615 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:46.986639  7292 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:46.986778  7292 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520401731-7292-0/minicluster-data/ts-0-root
uuid: "c4bd67ff39e14d379199b306453d78ca"
format_stamp: "Formatted at 2026-08-12 06:18:46 on dist-test-slave-8tdl"
I20260812 06:18:46.986881  7292 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520401731-7292-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520401731-7292-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520401731-7292-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:46.996361  7292 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:46.996872  7292 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:46.997216  7292 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:46.997769  7292 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:46.997834  7292 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:46.997901  7292 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:46.997954  7292 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:47.002724  7292 rpc_server.cc:307] RPC server started. Bound to: 127.7.31.1:41027
I20260812 06:18:47.002810  7687 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.7.31.1:41027 every 8 connection(s)
I20260812 06:18:47.008917  7688 heartbeater.cc:344] Connected to a master server at 127.7.31.62:36979
I20260812 06:18:47.009061  7688 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:47.009297  7688 heartbeater.cc:507] Master 127.7.31.62:36979 requested a full tablet report, sending...
I20260812 06:18:47.009974  7541 ts_manager.cc:194] Registered new tserver with Master: c4bd67ff39e14d379199b306453d78ca (127.7.31.1:41027)
I20260812 06:18:47.010088  7292 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.006823328s
I20260812 06:18:47.010927  7541 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:60202
I20260812 06:18:47.018739  7541 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:60218:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:47.028940  7649 tablet_service.cc:1511] Processing CreateTablet for tablet 53aea02ae1e347c9b016687f773e66a6 (DEFAULT_TABLE table=heavy-update-compaction-test [id=3dda00f9791f4ac1914d99c5f8039c7a]), partition=
I20260812 06:18:47.029286  7649 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 53aea02ae1e347c9b016687f773e66a6. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:47.031692  7700 tablet_bootstrap.cc:492] T 53aea02ae1e347c9b016687f773e66a6 P c4bd67ff39e14d379199b306453d78ca: Bootstrap starting.
I20260812 06:18:47.032663  7700 tablet_bootstrap.cc:654] T 53aea02ae1e347c9b016687f773e66a6 P c4bd67ff39e14d379199b306453d78ca: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:47.034018  7700 tablet_bootstrap.cc:492] T 53aea02ae1e347c9b016687f773e66a6 P c4bd67ff39e14d379199b306453d78ca: No bootstrap required, opened a new log
I20260812 06:18:47.034109  7700 ts_tablet_manager.cc:1403] T 53aea02ae1e347c9b016687f773e66a6 P c4bd67ff39e14d379199b306453d78ca: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:47.034739  7700 raft_consensus.cc:359] T 53aea02ae1e347c9b016687f773e66a6 P c4bd67ff39e14d379199b306453d78ca [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c4bd67ff39e14d379199b306453d78ca" member_type: VOTER last_known_addr { host: "127.7.31.1" port: 41027 } }
I20260812 06:18:47.034862  7700 raft_consensus.cc:385] T 53aea02ae1e347c9b016687f773e66a6 P c4bd67ff39e14d379199b306453d78ca [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:47.034888  7700 raft_consensus.cc:740] T 53aea02ae1e347c9b016687f773e66a6 P c4bd67ff39e14d379199b306453d78ca [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: c4bd67ff39e14d379199b306453d78ca, State: Initialized, Role: FOLLOWER
I20260812 06:18:47.034996  7700 consensus_queue.cc:260] T 53aea02ae1e347c9b016687f773e66a6 P c4bd67ff39e14d379199b306453d78ca [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: "c4bd67ff39e14d379199b306453d78ca" member_type: VOTER last_known_addr { host: "127.7.31.1" port: 41027 } }
I20260812 06:18:47.035109  7700 raft_consensus.cc:399] T 53aea02ae1e347c9b016687f773e66a6 P c4bd67ff39e14d379199b306453d78ca [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:47.035138  7700 raft_consensus.cc:493] T 53aea02ae1e347c9b016687f773e66a6 P c4bd67ff39e14d379199b306453d78ca [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:47.035192  7700 raft_consensus.cc:3060] T 53aea02ae1e347c9b016687f773e66a6 P c4bd67ff39e14d379199b306453d78ca [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:47.036026  7700 raft_consensus.cc:515] T 53aea02ae1e347c9b016687f773e66a6 P c4bd67ff39e14d379199b306453d78ca [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c4bd67ff39e14d379199b306453d78ca" member_type: VOTER last_known_addr { host: "127.7.31.1" port: 41027 } }
I20260812 06:18:47.036187  7700 leader_election.cc:304] T 53aea02ae1e347c9b016687f773e66a6 P c4bd67ff39e14d379199b306453d78ca [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: c4bd67ff39e14d379199b306453d78ca; no voters: 
I20260812 06:18:47.036444  7700 leader_election.cc:290] T 53aea02ae1e347c9b016687f773e66a6 P c4bd67ff39e14d379199b306453d78ca [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:47.036656  7703 raft_consensus.cc:2804] T 53aea02ae1e347c9b016687f773e66a6 P c4bd67ff39e14d379199b306453d78ca [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:47.036800  7700 ts_tablet_manager.cc:1434] T 53aea02ae1e347c9b016687f773e66a6 P c4bd67ff39e14d379199b306453d78ca: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:47.036895  7688 heartbeater.cc:499] Master 127.7.31.62:36979 was elected leader, sending a full tablet report...
I20260812 06:18:47.037134  7703 raft_consensus.cc:697] T 53aea02ae1e347c9b016687f773e66a6 P c4bd67ff39e14d379199b306453d78ca [term 1 LEADER]: Becoming Leader. State: Replica: c4bd67ff39e14d379199b306453d78ca, State: Running, Role: LEADER
I20260812 06:18:47.037317  7703 consensus_queue.cc:237] T 53aea02ae1e347c9b016687f773e66a6 P c4bd67ff39e14d379199b306453d78ca [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: "c4bd67ff39e14d379199b306453d78ca" member_type: VOTER last_known_addr { host: "127.7.31.1" port: 41027 } }
I20260812 06:18:47.038980  7541 catalog_manager.cc:5719] T 53aea02ae1e347c9b016687f773e66a6 P c4bd67ff39e14d379199b306453d78ca reported cstate change: term changed from 0 to 1, leader changed from <none> to c4bd67ff39e14d379199b306453d78ca (127.7.31.1). New cstate: current_term: 1 leader_uuid: "c4bd67ff39e14d379199b306453d78ca" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c4bd67ff39e14d379199b306453d78ca" member_type: VOTER last_known_addr { host: "127.7.31.1" port: 41027 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:47.103119  7292 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.058s	user 0.014s	sys 0.010s
I20260812 06:18:47.253976  7689 maintenance_manager.cc:419] P c4bd67ff39e14d379199b306453d78ca: Scheduling FlushMRSOp(53aea02ae1e347c9b016687f773e66a6): perf score=19.054940
I20260812 06:18:47.419644  7620 maintenance_manager.cc:643] P c4bd67ff39e14d379199b306453d78ca: FlushMRSOp(53aea02ae1e347c9b016687f773e66a6) complete. Timing: real 0.165s	user 0.129s	sys 0.036s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":79,"dirs.run_cpu_time_us":226,"dirs.run_wall_time_us":835,"drs_written":1,"lbm_read_time_us":91,"lbm_reads_lt_1ms":4,"lbm_write_time_us":42551,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":2432,"update_count":1500}
I20260812 06:18:47.420297  7689 maintenance_manager.cc:419] P c4bd67ff39e14d379199b306453d78ca: Scheduling LogGCOp(53aea02ae1e347c9b016687f773e66a6): free 20743880 bytes of WAL
I20260812 06:18:47.420557  7620 log_reader.cc:385] T 53aea02ae1e347c9b016687f773e66a6: removed 2 log segments from log reader
I20260812 06:18:47.420608  7620 log.cc:1079] T 53aea02ae1e347c9b016687f773e66a6 P c4bd67ff39e14d379199b306453d78ca: Deleting log segment in path: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520401731-7292-0/minicluster-data/ts-0-root/wals/53aea02ae1e347c9b016687f773e66a6/wal-000000001 (ops 1-6)
I20260812 06:18:47.420639  7620 log.cc:1079] T 53aea02ae1e347c9b016687f773e66a6 P c4bd67ff39e14d379199b306453d78ca: Deleting log segment in path: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520401731-7292-0/minicluster-data/ts-0-root/wals/53aea02ae1e347c9b016687f773e66a6/wal-000000002 (ops 7-11)
I20260812 06:18:47.425071  7620 maintenance_manager.cc:643] P c4bd67ff39e14d379199b306453d78ca: LogGCOp(53aea02ae1e347c9b016687f773e66a6) complete. Timing: real 0.005s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:18:47.425503  7689 maintenance_manager.cc:419] P c4bd67ff39e14d379199b306453d78ca: Scheduling UndoDeltaBlockGCOp(53aea02ae1e347c9b016687f773e66a6): 16411397 bytes on disk
I20260812 06:18:47.425961  7620 maintenance_manager.cc:643] P c4bd67ff39e14d379199b306453d78ca: UndoDeltaBlockGCOp(53aea02ae1e347c9b016687f773e66a6) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4}
I20260812 06:18:47.426600  7689 maintenance_manager.cc:419] P c4bd67ff39e14d379199b306453d78ca: Scheduling FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6): perf score=2.188937
I20260812 06:18:47.441931  7620 maintenance_manager.cc:643] P c4bd67ff39e14d379199b306453d78ca: FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5932,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:47.442382  7689 maintenance_manager.cc:419] P c4bd67ff39e14d379199b306453d78ca: Scheduling MajorDeltaCompactionOp(53aea02ae1e347c9b016687f773e66a6): perf score=1.000000
I20260812 06:18:47.581820  7620 maintenance_manager.cc:643] P c4bd67ff39e14d379199b306453d78ca: MajorDeltaCompactionOp(53aea02ae1e347c9b016687f773e66a6) complete. Timing: real 0.139s	user 0.119s	sys 0.020s 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":445,"lbm_read_time_us":8952,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27065,"lbm_writes_lt_1ms":443,"mutex_wait_us":24,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12672,"thread_start_us":326,"threads_started":5,"update_count":2000}
I20260812 06:18:47.582538  7689 maintenance_manager.cc:419] P c4bd67ff39e14d379199b306453d78ca: Scheduling FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6): perf score=11.118625
I20260812 06:18:47.625684  7620 maintenance_manager.cc:643] P c4bd67ff39e14d379199b306453d78ca: FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6) complete. Timing: real 0.043s	user 0.024s	sys 0.016s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":14382,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:47.626278  7689 maintenance_manager.cc:419] P c4bd67ff39e14d379199b306453d78ca: Scheduling FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6): perf score=2.188937
I20260812 06:18:47.636822  7620 maintenance_manager.cc:643] P c4bd67ff39e14d379199b306453d78ca: FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6) complete. Timing: real 0.010s	user 0.005s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3966,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:47.637348  7689 maintenance_manager.cc:419] P c4bd67ff39e14d379199b306453d78ca: Scheduling MajorDeltaCompactionOp(53aea02ae1e347c9b016687f773e66a6): perf score=1.000000
I20260812 06:18:47.804466  7620 maintenance_manager.cc:643] P c4bd67ff39e14d379199b306453d78ca: MajorDeltaCompactionOp(53aea02ae1e347c9b016687f773e66a6) complete. Timing: real 0.167s	user 0.128s	sys 0.039s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672269,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":495,"lbm_read_time_us":11559,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26356,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2000}
I20260812 06:18:47.805272  7689 maintenance_manager.cc:419] P c4bd67ff39e14d379199b306453d78ca: Scheduling FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6): perf score=10.126437
I20260812 06:18:47.852172  7620 maintenance_manager.cc:643] P c4bd67ff39e14d379199b306453d78ca: FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6) complete. Timing: real 0.047s	user 0.029s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16688,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:47.852728  7689 maintenance_manager.cc:419] P c4bd67ff39e14d379199b306453d78ca: Scheduling FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6): perf score=2.188937
I20260812 06:18:47.864846  7620 maintenance_manager.cc:643] P c4bd67ff39e14d379199b306453d78ca: FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4331,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:47.865562  7689 maintenance_manager.cc:419] P c4bd67ff39e14d379199b306453d78ca: Scheduling MajorDeltaCompactionOp(53aea02ae1e347c9b016687f773e66a6): perf score=1.000000
I20260812 06:18:47.993528  7620 maintenance_manager.cc:643] P c4bd67ff39e14d379199b306453d78ca: MajorDeltaCompactionOp(53aea02ae1e347c9b016687f773e66a6) complete. Timing: real 0.128s	user 0.100s	sys 0.028s 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":603,"lbm_read_time_us":10240,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24577,"lbm_writes_lt_1ms":443,"mutex_wait_us":43,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":19584,"update_count":2000}
I20260812 06:18:47.994338  7689 maintenance_manager.cc:419] P c4bd67ff39e14d379199b306453d78ca: Scheduling FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6): perf score=10.126437
I20260812 06:18:48.037707  7620 maintenance_manager.cc:643] P c4bd67ff39e14d379199b306453d78ca: FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6) complete. Timing: real 0.043s	user 0.020s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15225,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:48.038370  7689 maintenance_manager.cc:419] P c4bd67ff39e14d379199b306453d78ca: Scheduling FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6): perf score=2.188937
I20260812 06:18:48.055039  7620 maintenance_manager.cc:643] P c4bd67ff39e14d379199b306453d78ca: FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6) complete. Timing: real 0.016s	user 0.013s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5934,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:48.055580  7689 maintenance_manager.cc:419] P c4bd67ff39e14d379199b306453d78ca: Scheduling MajorDeltaCompactionOp(53aea02ae1e347c9b016687f773e66a6): perf score=1.000000
I20260812 06:18:48.184015  7620 maintenance_manager.cc:643] P c4bd67ff39e14d379199b306453d78ca: MajorDeltaCompactionOp(53aea02ae1e347c9b016687f773e66a6) complete. Timing: real 0.128s	user 0.092s	sys 0.035s 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":1544,"lbm_read_time_us":9727,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23772,"lbm_writes_lt_1ms":443,"mutex_wait_us":791,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":15232,"update_count":2000}
I20260812 06:18:48.184823  7689 maintenance_manager.cc:419] P c4bd67ff39e14d379199b306453d78ca: Scheduling FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6): perf score=10.126437
I20260812 06:18:48.233027  7620 maintenance_manager.cc:643] P c4bd67ff39e14d379199b306453d78ca: FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6) complete. Timing: real 0.048s	user 0.022s	sys 0.019s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":15295,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:48.233740  7689 maintenance_manager.cc:419] P c4bd67ff39e14d379199b306453d78ca: Scheduling FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6): perf score=2.188937
I20260812 06:18:48.244966  7620 maintenance_manager.cc:643] P c4bd67ff39e14d379199b306453d78ca: FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4409,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:48.245453  7689 maintenance_manager.cc:419] P c4bd67ff39e14d379199b306453d78ca: Scheduling MajorDeltaCompactionOp(53aea02ae1e347c9b016687f773e66a6): perf score=1.000000
I20260812 06:18:48.416625  7620 maintenance_manager.cc:643] P c4bd67ff39e14d379199b306453d78ca: MajorDeltaCompactionOp(53aea02ae1e347c9b016687f773e66a6) complete. Timing: real 0.171s	user 0.118s	sys 0.051s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1400,"lbm_read_time_us":12077,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28501,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":311,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12032,"update_count":2000}
I20260812 06:18:48.417235  7689 maintenance_manager.cc:419] P c4bd67ff39e14d379199b306453d78ca: Scheduling FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6): perf score=10.126437
I20260812 06:18:48.466228  7620 maintenance_manager.cc:643] P c4bd67ff39e14d379199b306453d78ca: FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6) complete. Timing: real 0.049s	user 0.031s	sys 0.013s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":20735,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:48.466884  7689 maintenance_manager.cc:419] P c4bd67ff39e14d379199b306453d78ca: Scheduling FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6): perf score=2.188937
I20260812 06:18:48.480481  7620 maintenance_manager.cc:643] P c4bd67ff39e14d379199b306453d78ca: FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4459,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:48.481236  7689 maintenance_manager.cc:419] P c4bd67ff39e14d379199b306453d78ca: Scheduling MajorDeltaCompactionOp(53aea02ae1e347c9b016687f773e66a6): perf score=1.000000
I20260812 06:18:48.612598  7620 maintenance_manager.cc:643] P c4bd67ff39e14d379199b306453d78ca: MajorDeltaCompactionOp(53aea02ae1e347c9b016687f773e66a6) complete. Timing: real 0.131s	user 0.097s	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":145,"lbm_read_time_us":9483,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24406,"lbm_writes_lt_1ms":443,"mutex_wait_us":2,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":20480,"update_count":2000}
I20260812 06:18:48.613435  7689 maintenance_manager.cc:419] P c4bd67ff39e14d379199b306453d78ca: Scheduling FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6): perf score=10.126437
I20260812 06:18:48.654846  7620 maintenance_manager.cc:643] P c4bd67ff39e14d379199b306453d78ca: FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6) complete. Timing: real 0.041s	user 0.030s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18407,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:48.655375  7689 maintenance_manager.cc:419] P c4bd67ff39e14d379199b306453d78ca: Scheduling FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6): perf score=2.188937
I20260812 06:18:48.668148  7620 maintenance_manager.cc:643] P c4bd67ff39e14d379199b306453d78ca: FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4943,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:48.668660  7689 maintenance_manager.cc:419] P c4bd67ff39e14d379199b306453d78ca: Scheduling FlushMRSOp(53aea02ae1e347c9b016687f773e66a6): perf score=1.000000
I20260812 06:18:48.701231  7620 maintenance_manager.cc:643] P c4bd67ff39e14d379199b306453d78ca: FlushMRSOp(53aea02ae1e347c9b016687f773e66a6) complete. Timing: real 0.032s	user 0.027s	sys 0.003s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":88,"dirs.run_cpu_time_us":312,"dirs.run_wall_time_us":1642,"drs_written":1,"lbm_read_time_us":42,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1516,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:48.701929  7689 maintenance_manager.cc:419] P c4bd67ff39e14d379199b306453d78ca: Scheduling LogGCOp(53aea02ae1e347c9b016687f773e66a6): free 112239310 bytes of WAL
I20260812 06:18:48.702188  7620 log_reader.cc:385] T 53aea02ae1e347c9b016687f773e66a6: removed 11 log segments from log reader
I20260812 06:18:48.702236  7620 log.cc:1079] T 53aea02ae1e347c9b016687f773e66a6 P c4bd67ff39e14d379199b306453d78ca: Deleting log segment in path: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520401731-7292-0/minicluster-data/ts-0-root/wals/53aea02ae1e347c9b016687f773e66a6/wal-000000003 (ops 12-16)
I20260812 06:18:48.702314  7620 log.cc:1079] T 53aea02ae1e347c9b016687f773e66a6 P c4bd67ff39e14d379199b306453d78ca: Deleting log segment in path: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520401731-7292-0/minicluster-data/ts-0-root/wals/53aea02ae1e347c9b016687f773e66a6/wal-000000004 (ops 17-21)
I20260812 06:18:48.702421  7620 log.cc:1079] T 53aea02ae1e347c9b016687f773e66a6 P c4bd67ff39e14d379199b306453d78ca: Deleting log segment in path: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520401731-7292-0/minicluster-data/ts-0-root/wals/53aea02ae1e347c9b016687f773e66a6/wal-000000005 (ops 22-26)
I20260812 06:18:48.702455  7620 log.cc:1079] T 53aea02ae1e347c9b016687f773e66a6 P c4bd67ff39e14d379199b306453d78ca: Deleting log segment in path: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520401731-7292-0/minicluster-data/ts-0-root/wals/53aea02ae1e347c9b016687f773e66a6/wal-000000006 (ops 27-31)
I20260812 06:18:48.702476  7620 log.cc:1079] T 53aea02ae1e347c9b016687f773e66a6 P c4bd67ff39e14d379199b306453d78ca: Deleting log segment in path: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520401731-7292-0/minicluster-data/ts-0-root/wals/53aea02ae1e347c9b016687f773e66a6/wal-000000007 (ops 32-36)
I20260812 06:18:48.702493  7620 log.cc:1079] T 53aea02ae1e347c9b016687f773e66a6 P c4bd67ff39e14d379199b306453d78ca: Deleting log segment in path: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520401731-7292-0/minicluster-data/ts-0-root/wals/53aea02ae1e347c9b016687f773e66a6/wal-000000008 (ops 37-41)
I20260812 06:18:48.702539  7620 log.cc:1079] T 53aea02ae1e347c9b016687f773e66a6 P c4bd67ff39e14d379199b306453d78ca: Deleting log segment in path: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520401731-7292-0/minicluster-data/ts-0-root/wals/53aea02ae1e347c9b016687f773e66a6/wal-000000009 (ops 42-46)
I20260812 06:18:48.702590  7620 log.cc:1079] T 53aea02ae1e347c9b016687f773e66a6 P c4bd67ff39e14d379199b306453d78ca: Deleting log segment in path: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520401731-7292-0/minicluster-data/ts-0-root/wals/53aea02ae1e347c9b016687f773e66a6/wal-000000010 (ops 47-50)
I20260812 06:18:48.702613  7620 log.cc:1079] T 53aea02ae1e347c9b016687f773e66a6 P c4bd67ff39e14d379199b306453d78ca: Deleting log segment in path: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520401731-7292-0/minicluster-data/ts-0-root/wals/53aea02ae1e347c9b016687f773e66a6/wal-000000011 (ops 51-55)
I20260812 06:18:48.702703  7620 log.cc:1079] T 53aea02ae1e347c9b016687f773e66a6 P c4bd67ff39e14d379199b306453d78ca: Deleting log segment in path: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520401731-7292-0/minicluster-data/ts-0-root/wals/53aea02ae1e347c9b016687f773e66a6/wal-000000012 (ops 56-60)
I20260812 06:18:48.702754  7620 log.cc:1079] T 53aea02ae1e347c9b016687f773e66a6 P c4bd67ff39e14d379199b306453d78ca: Deleting log segment in path: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520401731-7292-0/minicluster-data/ts-0-root/wals/53aea02ae1e347c9b016687f773e66a6/wal-000000013 (ops 61-65)
I20260812 06:18:48.729753  7620 maintenance_manager.cc:643] P c4bd67ff39e14d379199b306453d78ca: LogGCOp(53aea02ae1e347c9b016687f773e66a6) complete. Timing: real 0.028s	user 0.005s	sys 0.019s Metrics: {}
I20260812 06:18:48.730276  7689 maintenance_manager.cc:419] P c4bd67ff39e14d379199b306453d78ca: Scheduling FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6): perf score=6.157687
I20260812 06:18:48.759687  7620 maintenance_manager.cc:643] P c4bd67ff39e14d379199b306453d78ca: FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6) complete. Timing: real 0.029s	user 0.017s	sys 0.008s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":11297,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:18:48.760228  7689 maintenance_manager.cc:419] P c4bd67ff39e14d379199b306453d78ca: Scheduling MajorDeltaCompactionOp(53aea02ae1e347c9b016687f773e66a6): perf score=1.000000
I20260812 06:18:48.935022  7620 maintenance_manager.cc:643] P c4bd67ff39e14d379199b306453d78ca: MajorDeltaCompactionOp(53aea02ae1e347c9b016687f773e66a6) complete. Timing: real 0.175s	user 0.140s	sys 0.032s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877220,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1502,"lbm_read_time_us":12013,"lbm_reads_lt_1ms":665,"lbm_write_time_us":34151,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"thread_start_us":117,"threads_started":1,"update_count":3000}
I20260812 06:18:48.935716  7689 maintenance_manager.cc:419] P c4bd67ff39e14d379199b306453d78ca: Scheduling FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6): perf score=14.095187
I20260812 06:18:48.990088  7620 maintenance_manager.cc:643] P c4bd67ff39e14d379199b306453d78ca: FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6) complete. Timing: real 0.054s	user 0.035s	sys 0.016s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23715,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:48.991091  7689 maintenance_manager.cc:419] P c4bd67ff39e14d379199b306453d78ca: Scheduling UndoDeltaBlockGCOp(53aea02ae1e347c9b016687f773e66a6): 447 bytes on disk
I20260812 06:18:48.991942  7620 maintenance_manager.cc:643] P c4bd67ff39e14d379199b306453d78ca: UndoDeltaBlockGCOp(53aea02ae1e347c9b016687f773e66a6) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":125,"lbm_reads_lt_1ms":4}
I20260812 06:18:48.992677  7689 maintenance_manager.cc:419] P c4bd67ff39e14d379199b306453d78ca: Scheduling FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6): perf score=2.188937
I20260812 06:18:49.019630  7620 maintenance_manager.cc:643] P c4bd67ff39e14d379199b306453d78ca: FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6) complete. Timing: real 0.027s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5587,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:49.020153  7689 maintenance_manager.cc:419] P c4bd67ff39e14d379199b306453d78ca: Scheduling FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6): perf score=2.188937
I20260812 06:18:49.030931  7620 maintenance_manager.cc:643] P c4bd67ff39e14d379199b306453d78ca: FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3964,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:49.031550  7689 maintenance_manager.cc:419] P c4bd67ff39e14d379199b306453d78ca: Scheduling MajorDeltaCompactionOp(53aea02ae1e347c9b016687f773e66a6): perf score=1.000000
I20260812 06:18:49.222935  7620 maintenance_manager.cc:643] P c4bd67ff39e14d379199b306453d78ca: MajorDeltaCompactionOp(53aea02ae1e347c9b016687f773e66a6) complete. Timing: real 0.191s	user 0.143s	sys 0.040s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877220,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":813,"lbm_read_time_us":12669,"lbm_reads_lt_1ms":673,"lbm_write_time_us":36785,"lbm_writes_lt_1ms":643,"mutex_wait_us":308,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":8576,"update_count":3000}
I20260812 06:18:49.223695  7689 maintenance_manager.cc:419] P c4bd67ff39e14d379199b306453d78ca: Scheduling FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6): perf score=14.095187
I20260812 06:18:49.276857  7620 maintenance_manager.cc:643] P c4bd67ff39e14d379199b306453d78ca: FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6) complete. Timing: real 0.053s	user 0.031s	sys 0.020s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21301,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:49.277483  7689 maintenance_manager.cc:419] P c4bd67ff39e14d379199b306453d78ca: Scheduling FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6): perf score=2.188937
I20260812 06:18:49.294356  7620 maintenance_manager.cc:643] P c4bd67ff39e14d379199b306453d78ca: FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6) complete. Timing: real 0.017s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5915,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:49.294987  7689 maintenance_manager.cc:419] P c4bd67ff39e14d379199b306453d78ca: Scheduling MajorDeltaCompactionOp(53aea02ae1e347c9b016687f773e66a6): perf score=1.000000
I20260812 06:18:49.491442  7620 maintenance_manager.cc:643] P c4bd67ff39e14d379199b306453d78ca: MajorDeltaCompactionOp(53aea02ae1e347c9b016687f773e66a6) complete. Timing: real 0.196s	user 0.109s	sys 0.081s 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":892,"lbm_read_time_us":10432,"lbm_reads_lt_1ms":564,"lbm_write_time_us":33435,"lbm_writes_lt_1ms":543,"mutex_wait_us":292,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":2500}
I20260812 06:18:49.492214  7689 maintenance_manager.cc:419] P c4bd67ff39e14d379199b306453d78ca: Scheduling FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6): perf score=14.095187
I20260812 06:18:49.543177  7620 maintenance_manager.cc:643] P c4bd67ff39e14d379199b306453d78ca: FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6) complete. Timing: real 0.051s	user 0.041s	sys 0.008s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21848,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:49.543762  7689 maintenance_manager.cc:419] P c4bd67ff39e14d379199b306453d78ca: Scheduling FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6): perf score=2.188937
I20260812 06:18:49.555637  7620 maintenance_manager.cc:643] P c4bd67ff39e14d379199b306453d78ca: FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4183,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:49.556221  7689 maintenance_manager.cc:419] P c4bd67ff39e14d379199b306453d78ca: Scheduling MajorDeltaCompactionOp(53aea02ae1e347c9b016687f773e66a6): perf score=1.000000
I20260812 06:18:49.711627  7620 maintenance_manager.cc:643] P c4bd67ff39e14d379199b306453d78ca: MajorDeltaCompactionOp(53aea02ae1e347c9b016687f773e66a6) complete. Timing: real 0.155s	user 0.123s	sys 0.032s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":277,"lbm_read_time_us":10302,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32518,"lbm_writes_lt_1ms":543,"mutex_wait_us":65,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":2500}
I20260812 06:18:49.712343  7689 maintenance_manager.cc:419] P c4bd67ff39e14d379199b306453d78ca: Scheduling FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6): perf score=10.126437
I20260812 06:18:49.753461  7620 maintenance_manager.cc:643] P c4bd67ff39e14d379199b306453d78ca: FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6) complete. Timing: real 0.041s	user 0.025s	sys 0.012s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17704,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:49.754030  7689 maintenance_manager.cc:419] P c4bd67ff39e14d379199b306453d78ca: Scheduling FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6): perf score=2.188937
I20260812 06:18:49.768890  7620 maintenance_manager.cc:643] P c4bd67ff39e14d379199b306453d78ca: FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6) complete. Timing: real 0.015s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5231,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:49.769680  7689 maintenance_manager.cc:419] P c4bd67ff39e14d379199b306453d78ca: Scheduling MajorDeltaCompactionOp(53aea02ae1e347c9b016687f773e66a6): perf score=1.000000
I20260812 06:18:49.902661  7620 maintenance_manager.cc:643] P c4bd67ff39e14d379199b306453d78ca: MajorDeltaCompactionOp(53aea02ae1e347c9b016687f773e66a6) complete. Timing: real 0.133s	user 0.101s	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":416,"lbm_read_time_us":8199,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27974,"lbm_writes_lt_1ms":443,"mutex_wait_us":24,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:49.903509  7689 maintenance_manager.cc:419] P c4bd67ff39e14d379199b306453d78ca: Scheduling FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6): perf score=10.126437
I20260812 06:18:49.951112  7620 maintenance_manager.cc:643] P c4bd67ff39e14d379199b306453d78ca: FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6) complete. Timing: real 0.047s	user 0.036s	sys 0.003s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17165,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:49.951697  7689 maintenance_manager.cc:419] P c4bd67ff39e14d379199b306453d78ca: Scheduling FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6): perf score=2.188937
I20260812 06:18:49.967545  7620 maintenance_manager.cc:643] P c4bd67ff39e14d379199b306453d78ca: FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6) complete. Timing: real 0.016s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5831,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:49.968237  7689 maintenance_manager.cc:419] P c4bd67ff39e14d379199b306453d78ca: Scheduling MajorDeltaCompactionOp(53aea02ae1e347c9b016687f773e66a6): perf score=1.000000
I20260812 06:18:50.104297  7620 maintenance_manager.cc:643] P c4bd67ff39e14d379199b306453d78ca: MajorDeltaCompactionOp(53aea02ae1e347c9b016687f773e66a6) complete. Timing: real 0.136s	user 0.094s	sys 0.040s 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":197,"lbm_read_time_us":10172,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25739,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":33792,"update_count":2000}
I20260812 06:18:50.105046  7689 maintenance_manager.cc:419] P c4bd67ff39e14d379199b306453d78ca: Scheduling FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6): perf score=10.126437
I20260812 06:18:50.155766  7620 maintenance_manager.cc:643] P c4bd67ff39e14d379199b306453d78ca: FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6) complete. Timing: real 0.050s	user 0.023s	sys 0.023s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15325,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:50.156500  7689 maintenance_manager.cc:419] P c4bd67ff39e14d379199b306453d78ca: Scheduling FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6): perf score=2.188937
I20260812 06:18:50.173995  7620 maintenance_manager.cc:643] P c4bd67ff39e14d379199b306453d78ca: FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6) complete. Timing: real 0.017s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6577,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:50.174743  7689 maintenance_manager.cc:419] P c4bd67ff39e14d379199b306453d78ca: Scheduling FlushMRSOp(53aea02ae1e347c9b016687f773e66a6): perf score=1.000000
I20260812 06:18:50.222616  7620 maintenance_manager.cc:643] P c4bd67ff39e14d379199b306453d78ca: FlushMRSOp(53aea02ae1e347c9b016687f773e66a6) complete. Timing: real 0.048s	user 0.037s	sys 0.000s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":84,"dirs.run_cpu_time_us":178,"dirs.run_wall_time_us":1357,"drs_written":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1984,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:50.223405  7689 maintenance_manager.cc:419] P c4bd67ff39e14d379199b306453d78ca: Scheduling LogGCOp(53aea02ae1e347c9b016687f773e66a6): free 128867446 bytes of WAL
I20260812 06:18:50.223649  7620 log_reader.cc:385] T 53aea02ae1e347c9b016687f773e66a6: removed 13 log segments from log reader
I20260812 06:18:50.223691  7620 log.cc:1079] T 53aea02ae1e347c9b016687f773e66a6 P c4bd67ff39e14d379199b306453d78ca: Deleting log segment in path: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520401731-7292-0/minicluster-data/ts-0-root/wals/53aea02ae1e347c9b016687f773e66a6/wal-000000014 (ops 66-70)
I20260812 06:18:50.223721  7620 log.cc:1079] T 53aea02ae1e347c9b016687f773e66a6 P c4bd67ff39e14d379199b306453d78ca: Deleting log segment in path: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520401731-7292-0/minicluster-data/ts-0-root/wals/53aea02ae1e347c9b016687f773e66a6/wal-000000015 (ops 71-74)
I20260812 06:18:50.223783  7620 log.cc:1079] T 53aea02ae1e347c9b016687f773e66a6 P c4bd67ff39e14d379199b306453d78ca: Deleting log segment in path: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520401731-7292-0/minicluster-data/ts-0-root/wals/53aea02ae1e347c9b016687f773e66a6/wal-000000016 (ops 75-79)
I20260812 06:18:50.223835  7620 log.cc:1079] T 53aea02ae1e347c9b016687f773e66a6 P c4bd67ff39e14d379199b306453d78ca: Deleting log segment in path: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520401731-7292-0/minicluster-data/ts-0-root/wals/53aea02ae1e347c9b016687f773e66a6/wal-000000017 (ops 80-84)
I20260812 06:18:50.223881  7620 log.cc:1079] T 53aea02ae1e347c9b016687f773e66a6 P c4bd67ff39e14d379199b306453d78ca: Deleting log segment in path: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520401731-7292-0/minicluster-data/ts-0-root/wals/53aea02ae1e347c9b016687f773e66a6/wal-000000018 (ops 85-89)
I20260812 06:18:50.223902  7620 log.cc:1079] T 53aea02ae1e347c9b016687f773e66a6 P c4bd67ff39e14d379199b306453d78ca: Deleting log segment in path: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520401731-7292-0/minicluster-data/ts-0-root/wals/53aea02ae1e347c9b016687f773e66a6/wal-000000019 (ops 90-94)
I20260812 06:18:50.223960  7620 log.cc:1079] T 53aea02ae1e347c9b016687f773e66a6 P c4bd67ff39e14d379199b306453d78ca: Deleting log segment in path: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520401731-7292-0/minicluster-data/ts-0-root/wals/53aea02ae1e347c9b016687f773e66a6/wal-000000020 (ops 95-98)
I20260812 06:18:50.224004  7620 log.cc:1079] T 53aea02ae1e347c9b016687f773e66a6 P c4bd67ff39e14d379199b306453d78ca: Deleting log segment in path: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520401731-7292-0/minicluster-data/ts-0-root/wals/53aea02ae1e347c9b016687f773e66a6/wal-000000021 (ops 99-103)
I20260812 06:18:50.224041  7620 log.cc:1079] T 53aea02ae1e347c9b016687f773e66a6 P c4bd67ff39e14d379199b306453d78ca: Deleting log segment in path: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520401731-7292-0/minicluster-data/ts-0-root/wals/53aea02ae1e347c9b016687f773e66a6/wal-000000022 (ops 104-108)
I20260812 06:18:50.224100  7620 log.cc:1079] T 53aea02ae1e347c9b016687f773e66a6 P c4bd67ff39e14d379199b306453d78ca: Deleting log segment in path: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520401731-7292-0/minicluster-data/ts-0-root/wals/53aea02ae1e347c9b016687f773e66a6/wal-000000023 (ops 109-113)
I20260812 06:18:50.224140  7620 log.cc:1079] T 53aea02ae1e347c9b016687f773e66a6 P c4bd67ff39e14d379199b306453d78ca: Deleting log segment in path: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520401731-7292-0/minicluster-data/ts-0-root/wals/53aea02ae1e347c9b016687f773e66a6/wal-000000024 (ops 114-118)
I20260812 06:18:50.224180  7620 log.cc:1079] T 53aea02ae1e347c9b016687f773e66a6 P c4bd67ff39e14d379199b306453d78ca: Deleting log segment in path: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520401731-7292-0/minicluster-data/ts-0-root/wals/53aea02ae1e347c9b016687f773e66a6/wal-000000025 (ops 119-122)
I20260812 06:18:50.224220  7620 log.cc:1079] T 53aea02ae1e347c9b016687f773e66a6 P c4bd67ff39e14d379199b306453d78ca: Deleting log segment in path: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520401731-7292-0/minicluster-data/ts-0-root/wals/53aea02ae1e347c9b016687f773e66a6/wal-000000026 (ops 123-127)
I20260812 06:18:50.252503  7620 maintenance_manager.cc:643] P c4bd67ff39e14d379199b306453d78ca: LogGCOp(53aea02ae1e347c9b016687f773e66a6) complete. Timing: real 0.029s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:18:50.252974  7689 maintenance_manager.cc:419] P c4bd67ff39e14d379199b306453d78ca: Scheduling FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6): perf score=2.188937
I20260812 06:18:50.276674  7620 maintenance_manager.cc:643] P c4bd67ff39e14d379199b306453d78ca: FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6) complete. Timing: real 0.024s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102660,"delete_count":0,"lbm_write_time_us":6264,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:50.277212  7689 maintenance_manager.cc:419] P c4bd67ff39e14d379199b306453d78ca: Scheduling FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6): perf score=2.188937
I20260812 06:18:50.288173  7620 maintenance_manager.cc:643] P c4bd67ff39e14d379199b306453d78ca: FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6) complete. Timing: real 0.011s	user 0.004s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4060,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:50.288671  7689 maintenance_manager.cc:419] P c4bd67ff39e14d379199b306453d78ca: Scheduling MajorDeltaCompactionOp(53aea02ae1e347c9b016687f773e66a6): perf score=1.000000
I20260812 06:18:50.502339  7620 maintenance_manager.cc:643] P c4bd67ff39e14d379199b306453d78ca: MajorDeltaCompactionOp(53aea02ae1e347c9b016687f773e66a6) complete. Timing: real 0.213s	user 0.133s	sys 0.080s 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":765,"lbm_read_time_us":14272,"lbm_reads_lt_1ms":674,"lbm_write_time_us":35395,"lbm_writes_lt_1ms":643,"mutex_wait_us":75,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":37120,"thread_start_us":89,"threads_started":1,"update_count":3000}
I20260812 06:18:50.503134  7689 maintenance_manager.cc:419] P c4bd67ff39e14d379199b306453d78ca: Scheduling UndoDeltaBlockGCOp(53aea02ae1e347c9b016687f773e66a6): 472 bytes on disk
I20260812 06:18:50.503628  7620 maintenance_manager.cc:643] P c4bd67ff39e14d379199b306453d78ca: UndoDeltaBlockGCOp(53aea02ae1e347c9b016687f773e66a6) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4}
I20260812 06:18:50.504417  7689 maintenance_manager.cc:419] P c4bd67ff39e14d379199b306453d78ca: Scheduling FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6): perf score=14.095187
I20260812 06:18:50.566447  7620 maintenance_manager.cc:643] P c4bd67ff39e14d379199b306453d78ca: FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6) complete. Timing: real 0.062s	user 0.033s	sys 0.016s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":23159,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:50.567103  7689 maintenance_manager.cc:419] P c4bd67ff39e14d379199b306453d78ca: Scheduling FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6): perf score=2.188937
I20260812 06:18:50.577947  7620 maintenance_manager.cc:643] P c4bd67ff39e14d379199b306453d78ca: FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4000,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:50.578799  7689 maintenance_manager.cc:419] P c4bd67ff39e14d379199b306453d78ca: Scheduling MajorDeltaCompactionOp(53aea02ae1e347c9b016687f773e66a6): perf score=1.000000
I20260812 06:18:50.749058  7620 maintenance_manager.cc:643] P c4bd67ff39e14d379199b306453d78ca: MajorDeltaCompactionOp(53aea02ae1e347c9b016687f773e66a6) complete. Timing: real 0.170s	user 0.129s	sys 0.040s 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":325,"lbm_read_time_us":11915,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28520,"lbm_writes_lt_1ms":543,"mutex_wait_us":31,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":17920,"update_count":2500}
I20260812 06:18:50.749768  7689 maintenance_manager.cc:419] P c4bd67ff39e14d379199b306453d78ca: Scheduling FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6): perf score=14.095187
I20260812 06:18:50.808740  7620 maintenance_manager.cc:643] P c4bd67ff39e14d379199b306453d78ca: FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6) complete. Timing: real 0.059s	user 0.042s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20928,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:50.809424  7689 maintenance_manager.cc:419] P c4bd67ff39e14d379199b306453d78ca: Scheduling FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6): perf score=2.188937
I20260812 06:18:50.828083  7620 maintenance_manager.cc:643] P c4bd67ff39e14d379199b306453d78ca: FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6) complete. Timing: real 0.018s	user 0.016s	sys 0.001s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6982,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:50.828715  7689 maintenance_manager.cc:419] P c4bd67ff39e14d379199b306453d78ca: Scheduling MajorDeltaCompactionOp(53aea02ae1e347c9b016687f773e66a6): perf score=1.000000
I20260812 06:18:51.019392  7620 maintenance_manager.cc:643] P c4bd67ff39e14d379199b306453d78ca: MajorDeltaCompactionOp(53aea02ae1e347c9b016687f773e66a6) complete. Timing: real 0.190s	user 0.121s	sys 0.069s 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":232,"lbm_read_time_us":14199,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34359,"lbm_writes_lt_1ms":543,"mutex_wait_us":31,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2500}
I20260812 06:18:51.020099  7689 maintenance_manager.cc:419] P c4bd67ff39e14d379199b306453d78ca: Scheduling FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6): perf score=11.118625
I20260812 06:18:51.057520  7620 maintenance_manager.cc:643] P c4bd67ff39e14d379199b306453d78ca: FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6) complete. Timing: real 0.037s	user 0.023s	sys 0.012s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15654,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:51.058444  7689 maintenance_manager.cc:419] P c4bd67ff39e14d379199b306453d78ca: Scheduling FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6): perf score=2.188937
I20260812 06:18:51.080274  7620 maintenance_manager.cc:643] P c4bd67ff39e14d379199b306453d78ca: FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6) complete. Timing: real 0.022s	user 0.013s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4511,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:51.080919  7689 maintenance_manager.cc:419] P c4bd67ff39e14d379199b306453d78ca: Scheduling MajorDeltaCompactionOp(53aea02ae1e347c9b016687f773e66a6): perf score=1.000000
I20260812 06:18:51.249155  7620 maintenance_manager.cc:643] P c4bd67ff39e14d379199b306453d78ca: MajorDeltaCompactionOp(53aea02ae1e347c9b016687f773e66a6) complete. Timing: real 0.168s	user 0.111s	sys 0.044s 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":586,"lbm_read_time_us":9368,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26953,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14848,"update_count":2000}
I20260812 06:18:51.249811  7689 maintenance_manager.cc:419] P c4bd67ff39e14d379199b306453d78ca: Scheduling FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6): perf score=14.095187
I20260812 06:18:51.306067  7620 maintenance_manager.cc:643] P c4bd67ff39e14d379199b306453d78ca: FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6) complete. Timing: real 0.056s	user 0.012s	sys 0.040s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":28256,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:18:51.306742  7689 maintenance_manager.cc:419] P c4bd67ff39e14d379199b306453d78ca: Scheduling FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6): perf score=2.188937
I20260812 06:18:51.319409  7620 maintenance_manager.cc:643] P c4bd67ff39e14d379199b306453d78ca: FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4219,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:51.320086  7689 maintenance_manager.cc:419] P c4bd67ff39e14d379199b306453d78ca: Scheduling MajorDeltaCompactionOp(53aea02ae1e347c9b016687f773e66a6): perf score=1.000000
I20260812 06:18:51.475095  7620 maintenance_manager.cc:643] P c4bd67ff39e14d379199b306453d78ca: MajorDeltaCompactionOp(53aea02ae1e347c9b016687f773e66a6) complete. Timing: real 0.155s	user 0.122s	sys 0.032s 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":1038,"lbm_read_time_us":11305,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29092,"lbm_writes_lt_1ms":543,"mutex_wait_us":350,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12544,"update_count":2500}
I20260812 06:18:51.475770  7689 maintenance_manager.cc:419] P c4bd67ff39e14d379199b306453d78ca: Scheduling FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6): perf score=10.126437
I20260812 06:18:51.515900  7620 maintenance_manager.cc:643] P c4bd67ff39e14d379199b306453d78ca: FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6) complete. Timing: real 0.040s	user 0.030s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17727,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:51.516403  7689 maintenance_manager.cc:419] P c4bd67ff39e14d379199b306453d78ca: Scheduling FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6): perf score=2.188937
I20260812 06:18:51.526863  7620 maintenance_manager.cc:643] P c4bd67ff39e14d379199b306453d78ca: FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6) complete. Timing: real 0.010s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3916,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:51.527417  7689 maintenance_manager.cc:419] P c4bd67ff39e14d379199b306453d78ca: Scheduling MajorDeltaCompactionOp(53aea02ae1e347c9b016687f773e66a6): perf score=1.000000
I20260812 06:18:51.655593  7620 maintenance_manager.cc:643] P c4bd67ff39e14d379199b306453d78ca: MajorDeltaCompactionOp(53aea02ae1e347c9b016687f773e66a6) complete. Timing: real 0.128s	user 0.104s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":384,"lbm_read_time_us":9695,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25223,"lbm_writes_lt_1ms":443,"mutex_wait_us":49,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9984,"update_count":2000}
I20260812 06:18:51.656384  7689 maintenance_manager.cc:419] P c4bd67ff39e14d379199b306453d78ca: Scheduling FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6): perf score=10.126437
I20260812 06:18:51.694139  7620 maintenance_manager.cc:643] P c4bd67ff39e14d379199b306453d78ca: FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6) complete. Timing: real 0.038s	user 0.025s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14730,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:51.694948  7689 maintenance_manager.cc:419] P c4bd67ff39e14d379199b306453d78ca: Scheduling FlushMRSOp(53aea02ae1e347c9b016687f773e66a6): perf score=1.000000
I20260812 06:18:51.746941  7620 maintenance_manager.cc:643] P c4bd67ff39e14d379199b306453d78ca: FlushMRSOp(53aea02ae1e347c9b016687f773e66a6) complete. Timing: real 0.052s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1193505,"cfile_init":1,"dirs.queue_time_us":75,"dirs.run_cpu_time_us":270,"dirs.run_wall_time_us":1682,"drs_written":1,"lbm_read_time_us":41,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1715,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:51.747731  7689 maintenance_manager.cc:419] P c4bd67ff39e14d379199b306453d78ca: Scheduling LogGCOp(53aea02ae1e347c9b016687f773e66a6): free 112239497 bytes of WAL
I20260812 06:18:51.747974  7620 log_reader.cc:385] T 53aea02ae1e347c9b016687f773e66a6: removed 11 log segments from log reader
I20260812 06:18:51.748021  7620 log.cc:1079] T 53aea02ae1e347c9b016687f773e66a6 P c4bd67ff39e14d379199b306453d78ca: Deleting log segment in path: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520401731-7292-0/minicluster-data/ts-0-root/wals/53aea02ae1e347c9b016687f773e66a6/wal-000000027 (ops 128-132)
I20260812 06:18:51.748052  7620 log.cc:1079] T 53aea02ae1e347c9b016687f773e66a6 P c4bd67ff39e14d379199b306453d78ca: Deleting log segment in path: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520401731-7292-0/minicluster-data/ts-0-root/wals/53aea02ae1e347c9b016687f773e66a6/wal-000000028 (ops 133-137)
I20260812 06:18:51.748070  7620 log.cc:1079] T 53aea02ae1e347c9b016687f773e66a6 P c4bd67ff39e14d379199b306453d78ca: Deleting log segment in path: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520401731-7292-0/minicluster-data/ts-0-root/wals/53aea02ae1e347c9b016687f773e66a6/wal-000000029 (ops 138-142)
I20260812 06:18:51.748086  7620 log.cc:1079] T 53aea02ae1e347c9b016687f773e66a6 P c4bd67ff39e14d379199b306453d78ca: Deleting log segment in path: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520401731-7292-0/minicluster-data/ts-0-root/wals/53aea02ae1e347c9b016687f773e66a6/wal-000000030 (ops 143-147)
I20260812 06:18:51.748154  7620 log.cc:1079] T 53aea02ae1e347c9b016687f773e66a6 P c4bd67ff39e14d379199b306453d78ca: Deleting log segment in path: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520401731-7292-0/minicluster-data/ts-0-root/wals/53aea02ae1e347c9b016687f773e66a6/wal-000000031 (ops 148-152)
I20260812 06:18:51.748198  7620 log.cc:1079] T 53aea02ae1e347c9b016687f773e66a6 P c4bd67ff39e14d379199b306453d78ca: Deleting log segment in path: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520401731-7292-0/minicluster-data/ts-0-root/wals/53aea02ae1e347c9b016687f773e66a6/wal-000000032 (ops 153-157)
I20260812 06:18:51.748251  7620 log.cc:1079] T 53aea02ae1e347c9b016687f773e66a6 P c4bd67ff39e14d379199b306453d78ca: Deleting log segment in path: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520401731-7292-0/minicluster-data/ts-0-root/wals/53aea02ae1e347c9b016687f773e66a6/wal-000000033 (ops 158-162)
I20260812 06:18:51.748310  7620 log.cc:1079] T 53aea02ae1e347c9b016687f773e66a6 P c4bd67ff39e14d379199b306453d78ca: Deleting log segment in path: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520401731-7292-0/minicluster-data/ts-0-root/wals/53aea02ae1e347c9b016687f773e66a6/wal-000000034 (ops 163-166)
I20260812 06:18:51.748350  7620 log.cc:1079] T 53aea02ae1e347c9b016687f773e66a6 P c4bd67ff39e14d379199b306453d78ca: Deleting log segment in path: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520401731-7292-0/minicluster-data/ts-0-root/wals/53aea02ae1e347c9b016687f773e66a6/wal-000000035 (ops 167-171)
I20260812 06:18:51.748394  7620 log.cc:1079] T 53aea02ae1e347c9b016687f773e66a6 P c4bd67ff39e14d379199b306453d78ca: Deleting log segment in path: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520401731-7292-0/minicluster-data/ts-0-root/wals/53aea02ae1e347c9b016687f773e66a6/wal-000000036 (ops 172-176)
I20260812 06:18:51.748426  7620 log.cc:1079] T 53aea02ae1e347c9b016687f773e66a6 P c4bd67ff39e14d379199b306453d78ca: Deleting log segment in path: /tmp/dist-test-taskGYoIdl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520401731-7292-0/minicluster-data/ts-0-root/wals/53aea02ae1e347c9b016687f773e66a6/wal-000000037 (ops 177-181)
I20260812 06:18:51.773182  7620 maintenance_manager.cc:643] P c4bd67ff39e14d379199b306453d78ca: LogGCOp(53aea02ae1e347c9b016687f773e66a6) complete. Timing: real 0.025s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:18:51.773674  7689 maintenance_manager.cc:419] P c4bd67ff39e14d379199b306453d78ca: Scheduling FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6): perf score=7.149875
I20260812 06:18:51.797712  7620 maintenance_manager.cc:643] P c4bd67ff39e14d379199b306453d78ca: FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6) complete. Timing: real 0.024s	user 0.021s	sys 0.000s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":9922,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:18:51.798347  7689 maintenance_manager.cc:419] P c4bd67ff39e14d379199b306453d78ca: Scheduling UndoDeltaBlockGCOp(53aea02ae1e347c9b016687f773e66a6): 463 bytes on disk
I20260812 06:18:51.798908  7620 maintenance_manager.cc:643] P c4bd67ff39e14d379199b306453d78ca: UndoDeltaBlockGCOp(53aea02ae1e347c9b016687f773e66a6) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":107,"lbm_reads_lt_1ms":4}
I20260812 06:18:51.799479  7689 maintenance_manager.cc:419] P c4bd67ff39e14d379199b306453d78ca: Scheduling FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6): perf score=2.188937
I20260812 06:18:51.815322  7620 maintenance_manager.cc:643] P c4bd67ff39e14d379199b306453d78ca: FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6) complete. Timing: real 0.016s	user 0.012s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5745,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:51.815923  7689 maintenance_manager.cc:419] P c4bd67ff39e14d379199b306453d78ca: Scheduling MajorDeltaCompactionOp(53aea02ae1e347c9b016687f773e66a6): perf score=1.000000
I20260812 06:18:51.989817  7620 maintenance_manager.cc:643] P c4bd67ff39e14d379199b306453d78ca: MajorDeltaCompactionOp(53aea02ae1e347c9b016687f773e66a6) complete. Timing: real 0.174s	user 0.131s	sys 0.040s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877212,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":653,"lbm_read_time_us":13518,"lbm_reads_lt_1ms":665,"lbm_write_time_us":33227,"lbm_writes_lt_1ms":643,"mutex_wait_us":51,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":129536,"thread_start_us":83,"threads_started":1,"update_count":3000}
I20260812 06:18:51.990551  7689 maintenance_manager.cc:419] P c4bd67ff39e14d379199b306453d78ca: Scheduling FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6): perf score=14.095187
I20260812 06:18:52.048817  7620 maintenance_manager.cc:643] P c4bd67ff39e14d379199b306453d78ca: FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6) complete. Timing: real 0.058s	user 0.032s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25018,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:52.049343  7689 maintenance_manager.cc:419] P c4bd67ff39e14d379199b306453d78ca: Scheduling FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6): perf score=2.188937
I20260812 06:18:52.064368  7620 maintenance_manager.cc:643] P c4bd67ff39e14d379199b306453d78ca: FlushDeltaMemStoresOp(53aea02ae1e347c9b016687f773e66a6) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5589,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:52.064960  7689 maintenance_manager.cc:419] P c4bd67ff39e14d379199b306453d78ca: Scheduling MajorDeltaCompactionOp(53aea02ae1e347c9b016687f773e66a6): perf score=1.000000
I20260812 06:18:52.125504  7292 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.022s	user 1.838s	sys 0.136s
I20260812 06:18:52.187796  7292 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.062s	user 0.002s	sys 0.000s
I20260812 06:18:52.188338  7292 tablet_server.cc:179] TabletServer@127.7.31.1:0 shutting down...
I20260812 06:18:52.211148  7620 maintenance_manager.cc:643] P c4bd67ff39e14d379199b306453d78ca: MajorDeltaCompactionOp(53aea02ae1e347c9b016687f773e66a6) complete. Timing: real 0.146s	user 0.121s	sys 0.024s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1130,"lbm_read_time_us":10074,"lbm_reads_lt_1ms":568,"lbm_write_time_us":28298,"lbm_writes_lt_1ms":543,"mutex_wait_us":78,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":26496,"update_count":2500}
I20260812 06:18:52.211939  7292 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:52.212237  7292 tablet_replica.cc:333] T 53aea02ae1e347c9b016687f773e66a6 P c4bd67ff39e14d379199b306453d78ca: stopping tablet replica
I20260812 06:18:52.212405  7292 raft_consensus.cc:2243] T 53aea02ae1e347c9b016687f773e66a6 P c4bd67ff39e14d379199b306453d78ca [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:52.212595  7292 raft_consensus.cc:2272] T 53aea02ae1e347c9b016687f773e66a6 P c4bd67ff39e14d379199b306453d78ca [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:52.230171  7292 tablet_server.cc:196] TabletServer@127.7.31.1:0 shutdown complete.
I20260812 06:18:52.256937  7292 master.cc:562] Master@127.7.31.62:36979 shutting down...
I20260812 06:18:52.261013  7292 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 55f3814e9ddd41499a2f66997872581f [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:52.261197  7292 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 55f3814e9ddd41499a2f66997872581f [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:52.261250  7292 tablet_replica.cc:333] T 00000000000000000000000000000000 P 55f3814e9ddd41499a2f66997872581f: stopping tablet replica
I20260812 06:18:52.273674  7292 master.cc:584] Master@127.7.31.62:36979 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5494 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11953 ms total)

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