[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:19:47.528925  8548 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.8.89.62:33429
I20260812 06:19:47.529847  8548 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:19:47.530433  8548 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:47.536391  8565 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:47.536437  8562 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:19:47.536580  8560 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:47.537184  8548 server_base.cc:1061] running on GCE node
I20260812 06:19:47.537639  8548 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:47.537734  8548 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:47.537775  8548 hybrid_clock.cc:648] HybridClock initialized: now 1786515587537773 us; error 0 us; skew 500 ppm
I20260812 06:19:47.539453  8548 webserver.cc:533] Webserver started at http://127.8.89.62:43773/ using document root <none> and password file <none>
I20260812 06:19:47.539961  8548 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:47.540023  8548 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:47.540241  8548 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:47.541797  8548 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587518819-8548-0/minicluster-data/master-0-root/instance:
uuid: "9b060c2c9e964c8f9a9a6a21fdc00eda"
format_stamp: "Formatted at 2026-08-12 06:19:47 on dist-test-slave-tc2s"
I20260812 06:19:47.545147  8548 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:19:47.547129  8573 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:47.548048  8548 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:19:47.548146  8548 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587518819-8548-0/minicluster-data/master-0-root
uuid: "9b060c2c9e964c8f9a9a6a21fdc00eda"
format_stamp: "Formatted at 2026-08-12 06:19:47 on dist-test-slave-tc2s"
I20260812 06:19:47.548237  8548 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587518819-8548-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587518819-8548-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587518819-8548-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:47.561094  8548 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:47.561626  8548 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:19:47.561762  8548 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:47.568854  8664 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.8.89.62:33429 every 8 connection(s)
I20260812 06:19:47.568868  8548 rpc_server.cc:307] RPC server started. Bound to: 127.8.89.62:33429
I20260812 06:19:47.571007  8666 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:47.576095  8666 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 9b060c2c9e964c8f9a9a6a21fdc00eda: Bootstrap starting.
I20260812 06:19:47.578307  8666 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 9b060c2c9e964c8f9a9a6a21fdc00eda: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:47.579141  8666 log.cc:826] T 00000000000000000000000000000000 P 9b060c2c9e964c8f9a9a6a21fdc00eda: Log is configured to *not* fsync() on all Append() calls
I20260812 06:19:47.580627  8666 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 9b060c2c9e964c8f9a9a6a21fdc00eda: No bootstrap required, opened a new log
I20260812 06:19:47.583237  8666 raft_consensus.cc:359] T 00000000000000000000000000000000 P 9b060c2c9e964c8f9a9a6a21fdc00eda [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9b060c2c9e964c8f9a9a6a21fdc00eda" member_type: VOTER }
I20260812 06:19:47.583395  8666 raft_consensus.cc:385] T 00000000000000000000000000000000 P 9b060c2c9e964c8f9a9a6a21fdc00eda [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:47.583461  8666 raft_consensus.cc:740] T 00000000000000000000000000000000 P 9b060c2c9e964c8f9a9a6a21fdc00eda [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 9b060c2c9e964c8f9a9a6a21fdc00eda, State: Initialized, Role: FOLLOWER
I20260812 06:19:47.584034  8666 consensus_queue.cc:260] T 00000000000000000000000000000000 P 9b060c2c9e964c8f9a9a6a21fdc00eda [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: "9b060c2c9e964c8f9a9a6a21fdc00eda" member_type: VOTER }
I20260812 06:19:47.584184  8666 raft_consensus.cc:399] T 00000000000000000000000000000000 P 9b060c2c9e964c8f9a9a6a21fdc00eda [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:47.584247  8666 raft_consensus.cc:493] T 00000000000000000000000000000000 P 9b060c2c9e964c8f9a9a6a21fdc00eda [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:47.584359  8666 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 9b060c2c9e964c8f9a9a6a21fdc00eda [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:47.585037  8666 raft_consensus.cc:515] T 00000000000000000000000000000000 P 9b060c2c9e964c8f9a9a6a21fdc00eda [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9b060c2c9e964c8f9a9a6a21fdc00eda" member_type: VOTER }
I20260812 06:19:47.585417  8666 leader_election.cc:304] T 00000000000000000000000000000000 P 9b060c2c9e964c8f9a9a6a21fdc00eda [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: 9b060c2c9e964c8f9a9a6a21fdc00eda; no voters: 
I20260812 06:19:47.585682  8666 leader_election.cc:290] T 00000000000000000000000000000000 P 9b060c2c9e964c8f9a9a6a21fdc00eda [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:47.585799  8670 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 9b060c2c9e964c8f9a9a6a21fdc00eda [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:47.586028  8670 raft_consensus.cc:697] T 00000000000000000000000000000000 P 9b060c2c9e964c8f9a9a6a21fdc00eda [term 1 LEADER]: Becoming Leader. State: Replica: 9b060c2c9e964c8f9a9a6a21fdc00eda, State: Running, Role: LEADER
I20260812 06:19:47.586391  8670 consensus_queue.cc:237] T 00000000000000000000000000000000 P 9b060c2c9e964c8f9a9a6a21fdc00eda [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: "9b060c2c9e964c8f9a9a6a21fdc00eda" member_type: VOTER }
I20260812 06:19:47.586565  8666 sys_catalog.cc:565] T 00000000000000000000000000000000 P 9b060c2c9e964c8f9a9a6a21fdc00eda [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:47.588024  8673 sys_catalog.cc:455] T 00000000000000000000000000000000 P 9b060c2c9e964c8f9a9a6a21fdc00eda [sys.catalog]: SysCatalogTable state changed. Reason: New leader 9b060c2c9e964c8f9a9a6a21fdc00eda. Latest consensus state: current_term: 1 leader_uuid: "9b060c2c9e964c8f9a9a6a21fdc00eda" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9b060c2c9e964c8f9a9a6a21fdc00eda" member_type: VOTER } }
I20260812 06:19:47.588066  8671 sys_catalog.cc:455] T 00000000000000000000000000000000 P 9b060c2c9e964c8f9a9a6a21fdc00eda [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "9b060c2c9e964c8f9a9a6a21fdc00eda" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9b060c2c9e964c8f9a9a6a21fdc00eda" member_type: VOTER } }
I20260812 06:19:47.588127  8673 sys_catalog.cc:458] T 00000000000000000000000000000000 P 9b060c2c9e964c8f9a9a6a21fdc00eda [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:47.588156  8671 sys_catalog.cc:458] T 00000000000000000000000000000000 P 9b060c2c9e964c8f9a9a6a21fdc00eda [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:47.588497  8687 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:47.588726  8548 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:47.591171  8687 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:47.595669  8687 catalog_manager.cc:1383] Generated new cluster ID: 80fcf763c3884672bd4b79797a2733d3
I20260812 06:19:47.595715  8687 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:47.600713  8687 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:47.601406  8687 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:47.607513  8687 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 9b060c2c9e964c8f9a9a6a21fdc00eda: Generated new TSK 0
I20260812 06:19:47.607981  8687 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:47.621155  8548 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:47.623890  8708 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:47.623854  8703 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:47.623924  8704 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:47.624042  8548 server_base.cc:1061] running on GCE node
I20260812 06:19:47.624334  8548 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:47.624383  8548 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:47.624404  8548 hybrid_clock.cc:648] HybridClock initialized: now 1786515587624404 us; error 0 us; skew 500 ppm
I20260812 06:19:47.625283  8548 webserver.cc:533] Webserver started at http://127.8.89.1:43235/ using document root <none> and password file <none>
I20260812 06:19:47.625437  8548 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:47.625488  8548 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:47.625560  8548 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:47.625991  8548 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587518819-8548-0/minicluster-data/ts-0-root/instance:
uuid: "655bc2a4745e48098b9da07139010290"
format_stamp: "Formatted at 2026-08-12 06:19:47 on dist-test-slave-tc2s"
I20260812 06:19:47.627689  8548 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:47.628758  8720 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:47.629024  8548 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:47.629097  8548 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587518819-8548-0/minicluster-data/ts-0-root
uuid: "655bc2a4745e48098b9da07139010290"
format_stamp: "Formatted at 2026-08-12 06:19:47 on dist-test-slave-tc2s"
I20260812 06:19:47.629161  8548 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587518819-8548-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587518819-8548-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587518819-8548-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:47.652349  8548 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:47.652768  8548 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:47.653268  8548 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:47.654284  8548 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:47.654351  8548 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:47.654407  8548 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:47.654438  8548 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:47.661022  8548 rpc_server.cc:307] RPC server started. Bound to: 127.8.89.1:42375
I20260812 06:19:47.661078  8827 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.8.89.1:42375 every 8 connection(s)
I20260812 06:19:47.673038  8828 heartbeater.cc:344] Connected to a master server at 127.8.89.62:33429
I20260812 06:19:47.673259  8828 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:47.673656  8828 heartbeater.cc:507] Master 127.8.89.62:33429 requested a full tablet report, sending...
I20260812 06:19:47.675076  8603 ts_manager.cc:194] Registered new tserver with Master: 655bc2a4745e48098b9da07139010290 (127.8.89.1:42375)
I20260812 06:19:47.675289  8548 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.01366554s
I20260812 06:19:47.676524  8603 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:52188
I20260812 06:19:47.684198  8603 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:52200:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:47.697103  8762 tablet_service.cc:1511] Processing CreateTablet for tablet 4e4dd15378b443c5b4fd56084d980bbb (DEFAULT_TABLE table=heavy-update-compaction-test [id=84988b8413fc473a9887982da0fee860]), partition=
I20260812 06:19:47.697532  8762 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 4e4dd15378b443c5b4fd56084d980bbb. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:47.699678  8853 tablet_bootstrap.cc:492] T 4e4dd15378b443c5b4fd56084d980bbb P 655bc2a4745e48098b9da07139010290: Bootstrap starting.
I20260812 06:19:47.700505  8853 tablet_bootstrap.cc:654] T 4e4dd15378b443c5b4fd56084d980bbb P 655bc2a4745e48098b9da07139010290: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:47.701570  8853 tablet_bootstrap.cc:492] T 4e4dd15378b443c5b4fd56084d980bbb P 655bc2a4745e48098b9da07139010290: No bootstrap required, opened a new log
I20260812 06:19:47.701649  8853 ts_tablet_manager.cc:1403] T 4e4dd15378b443c5b4fd56084d980bbb P 655bc2a4745e48098b9da07139010290: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:19:47.702090  8853 raft_consensus.cc:359] T 4e4dd15378b443c5b4fd56084d980bbb P 655bc2a4745e48098b9da07139010290 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "655bc2a4745e48098b9da07139010290" member_type: VOTER last_known_addr { host: "127.8.89.1" port: 42375 } }
I20260812 06:19:47.702184  8853 raft_consensus.cc:385] T 4e4dd15378b443c5b4fd56084d980bbb P 655bc2a4745e48098b9da07139010290 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:47.702206  8853 raft_consensus.cc:740] T 4e4dd15378b443c5b4fd56084d980bbb P 655bc2a4745e48098b9da07139010290 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 655bc2a4745e48098b9da07139010290, State: Initialized, Role: FOLLOWER
I20260812 06:19:47.702325  8853 consensus_queue.cc:260] T 4e4dd15378b443c5b4fd56084d980bbb P 655bc2a4745e48098b9da07139010290 [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: "655bc2a4745e48098b9da07139010290" member_type: VOTER last_known_addr { host: "127.8.89.1" port: 42375 } }
I20260812 06:19:47.702407  8853 raft_consensus.cc:399] T 4e4dd15378b443c5b4fd56084d980bbb P 655bc2a4745e48098b9da07139010290 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:47.702433  8853 raft_consensus.cc:493] T 4e4dd15378b443c5b4fd56084d980bbb P 655bc2a4745e48098b9da07139010290 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:47.702479  8853 raft_consensus.cc:3060] T 4e4dd15378b443c5b4fd56084d980bbb P 655bc2a4745e48098b9da07139010290 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:47.703142  8853 raft_consensus.cc:515] T 4e4dd15378b443c5b4fd56084d980bbb P 655bc2a4745e48098b9da07139010290 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "655bc2a4745e48098b9da07139010290" member_type: VOTER last_known_addr { host: "127.8.89.1" port: 42375 } }
I20260812 06:19:47.703261  8853 leader_election.cc:304] T 4e4dd15378b443c5b4fd56084d980bbb P 655bc2a4745e48098b9da07139010290 [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: 655bc2a4745e48098b9da07139010290; no voters: 
I20260812 06:19:47.703449  8853 leader_election.cc:290] T 4e4dd15378b443c5b4fd56084d980bbb P 655bc2a4745e48098b9da07139010290 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:47.703555  8856 raft_consensus.cc:2804] T 4e4dd15378b443c5b4fd56084d980bbb P 655bc2a4745e48098b9da07139010290 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:47.703729  8856 raft_consensus.cc:697] T 4e4dd15378b443c5b4fd56084d980bbb P 655bc2a4745e48098b9da07139010290 [term 1 LEADER]: Becoming Leader. State: Replica: 655bc2a4745e48098b9da07139010290, State: Running, Role: LEADER
I20260812 06:19:47.703774  8853 ts_tablet_manager.cc:1434] T 4e4dd15378b443c5b4fd56084d980bbb P 655bc2a4745e48098b9da07139010290: Time spent starting tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:47.703934  8856 consensus_queue.cc:237] T 4e4dd15378b443c5b4fd56084d980bbb P 655bc2a4745e48098b9da07139010290 [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: "655bc2a4745e48098b9da07139010290" member_type: VOTER last_known_addr { host: "127.8.89.1" port: 42375 } }
I20260812 06:19:47.704054  8828 heartbeater.cc:499] Master 127.8.89.62:33429 was elected leader, sending a full tablet report...
I20260812 06:19:47.706377  8603 catalog_manager.cc:5719] T 4e4dd15378b443c5b4fd56084d980bbb P 655bc2a4745e48098b9da07139010290 reported cstate change: term changed from 0 to 1, leader changed from <none> to 655bc2a4745e48098b9da07139010290 (127.8.89.1). New cstate: current_term: 1 leader_uuid: "655bc2a4745e48098b9da07139010290" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "655bc2a4745e48098b9da07139010290" member_type: VOTER last_known_addr { host: "127.8.89.1" port: 42375 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:47.769106  8548 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.057s	user 0.018s	sys 0.008s
I20260812 06:19:47.912189  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling FlushMRSOp(4e4dd15378b443c5b4fd56084d980bbb): perf score=19.054940
I20260812 06:19:48.101824  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: FlushMRSOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.189s	user 0.145s	sys 0.039s Metrics: {"bytes_written":15999661,"cfile_init":1,"compiler_manager_pool.queue_time_us":199,"delete_count":0,"dirs.queue_time_us":61,"dirs.run_cpu_time_us":213,"dirs.run_wall_time_us":808,"drs_written":1,"lbm_read_time_us":69,"lbm_reads_lt_1ms":4,"lbm_write_time_us":46871,"lbm_writes_lt_1ms":857,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"thread_start_us":101,"threads_started":1,"update_count":1950}
I20260812 06:19:48.103145  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling LogGCOp(4e4dd15378b443c5b4fd56084d980bbb): free 20743880 bytes of WAL
I20260812 06:19:48.103443  8728 log_reader.cc:385] T 4e4dd15378b443c5b4fd56084d980bbb: removed 2 log segments from log reader
I20260812 06:19:48.103513  8728 log.cc:1079] T 4e4dd15378b443c5b4fd56084d980bbb P 655bc2a4745e48098b9da07139010290: Deleting log segment in path: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587518819-8548-0/minicluster-data/ts-0-root/wals/4e4dd15378b443c5b4fd56084d980bbb/wal-000000001 (ops 1-6)
I20260812 06:19:48.103570  8728 log.cc:1079] T 4e4dd15378b443c5b4fd56084d980bbb P 655bc2a4745e48098b9da07139010290: Deleting log segment in path: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587518819-8548-0/minicluster-data/ts-0-root/wals/4e4dd15378b443c5b4fd56084d980bbb/wal-000000002 (ops 7-11)
I20260812 06:19:48.108747  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: LogGCOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.005s	user 0.003s	sys 0.000s Metrics: {}
I20260812 06:19:48.109073  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb): perf score=5.165500
I20260812 06:19:48.129930  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.021s	user 0.011s	sys 0.008s Metrics: {"bytes_written":6523088,"delete_count":0,"lbm_write_time_us":8712,"lbm_writes_lt_1ms":162,"reinsert_count":0,"update_count":795}
I20260812 06:19:48.130401  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling UndoDeltaBlockGCOp(4e4dd15378b443c5b4fd56084d980bbb): 16821649 bytes on disk
I20260812 06:19:48.130981  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: UndoDeltaBlockGCOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4}
I20260812 06:19:48.131372  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb): perf score=1.000000
I20260812 06:19:48.138537  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.007s	user 0.000s	sys 0.006s Metrics: {"bytes_written":1682177,"delete_count":0,"lbm_write_time_us":2327,"lbm_writes_lt_1ms":44,"reinsert_count":0,"update_count":205}
I20260812 06:19:48.138919  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling MajorDeltaCompactionOp(4e4dd15378b443c5b4fd56084d980bbb): perf score=1.000000
I20260812 06:19:48.317489  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: MajorDeltaCompactionOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.178s	user 0.118s	sys 0.059s Metrics: {"cfile_cache_miss":623,"cfile_cache_miss_bytes":28507916,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":509,"lbm_read_time_us":12517,"lbm_reads_lt_1ms":659,"lbm_write_time_us":31709,"lbm_writes_lt_1ms":633,"peak_mem_usage":74091738,"reinsert_count":0,"thread_start_us":277,"threads_started":5,"update_count":2950}
I20260812 06:19:48.318045  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb): perf score=14.095187
I20260812 06:19:48.369639  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.051s	user 0.026s	sys 0.013s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18960,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:48.370157  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb): perf score=2.188937
I20260812 06:19:48.380409  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4017,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:48.380873  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling MajorDeltaCompactionOp(4e4dd15378b443c5b4fd56084d980bbb): perf score=1.000000
I20260812 06:19:48.541559  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: MajorDeltaCompactionOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.161s	user 0.120s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":161,"lbm_read_time_us":12804,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28776,"lbm_writes_lt_1ms":543,"mutex_wait_us":73,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3456,"update_count":2500}
I20260812 06:19:48.543095  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb): perf score=10.126437
I20260812 06:19:48.577450  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.034s	user 0.026s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13436,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:48.578343  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb): perf score=2.188937
I20260812 06:19:48.591730  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5442,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:48.592260  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling MajorDeltaCompactionOp(4e4dd15378b443c5b4fd56084d980bbb): perf score=1.000000
I20260812 06:19:48.731914  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: MajorDeltaCompactionOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.139s	user 0.080s	sys 0.059s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713271,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":525,"lbm_read_time_us":9627,"lbm_reads_lt_1ms":468,"lbm_write_time_us":24459,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:19:48.732411  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb): perf score=10.126437
I20260812 06:19:48.762315  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.029s	user 0.020s	sys 0.008s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":12520,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:48.762840  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb): perf score=2.188937
I20260812 06:19:48.773778  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4130,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:48.774394  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling MajorDeltaCompactionOp(4e4dd15378b443c5b4fd56084d980bbb): perf score=1.000000
I20260812 06:19:48.884207  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: MajorDeltaCompactionOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.110s	user 0.075s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713274,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":197,"lbm_read_time_us":7502,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20443,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3200,"update_count":2000}
I20260812 06:19:48.884666  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb): perf score=10.126437
I20260812 06:19:48.924608  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.040s	user 0.015s	sys 0.015s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14574,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:48.925087  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb): perf score=2.188937
I20260812 06:19:48.934643  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3572,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:48.935063  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling MajorDeltaCompactionOp(4e4dd15378b443c5b4fd56084d980bbb): perf score=1.000000
I20260812 06:19:49.051653  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: MajorDeltaCompactionOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.116s	user 0.090s	sys 0.026s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713273,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":153,"lbm_read_time_us":9560,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20911,"lbm_writes_lt_1ms":443,"mutex_wait_us":28,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":69248,"update_count":2000}
I20260812 06:19:49.052103  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb): perf score=10.126437
I20260812 06:19:49.097333  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.045s	user 0.021s	sys 0.014s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13914,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:49.097829  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb): perf score=2.188937
I20260812 06:19:49.107797  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3814,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:49.108201  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling MajorDeltaCompactionOp(4e4dd15378b443c5b4fd56084d980bbb): perf score=1.000000
I20260812 06:19:49.242323  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: MajorDeltaCompactionOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.134s	user 0.088s	sys 0.046s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":875,"lbm_read_time_us":10345,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21159,"lbm_writes_lt_1ms":443,"mutex_wait_us":254,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2000}
I20260812 06:19:49.242811  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb): perf score=10.126437
I20260812 06:19:49.283887  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.041s	user 0.011s	sys 0.018s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13687,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:49.284325  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb): perf score=2.188937
I20260812 06:19:49.294176  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.010s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3785,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:49.294682  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling FlushMRSOp(4e4dd15378b443c5b4fd56084d980bbb): perf score=1.000000
I20260812 06:19:49.321921  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: FlushMRSOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.027s	user 0.022s	sys 0.004s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":57,"dirs.run_cpu_time_us":212,"dirs.run_wall_time_us":1166,"drs_written":1,"lbm_read_time_us":44,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1647,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:49.322659  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling LogGCOp(4e4dd15378b443c5b4fd56084d980bbb): free 124257244 bytes of WAL
I20260812 06:19:49.322875  8728 log_reader.cc:385] T 4e4dd15378b443c5b4fd56084d980bbb: removed 12 log segments from log reader
I20260812 06:19:49.322921  8728 log.cc:1079] T 4e4dd15378b443c5b4fd56084d980bbb P 655bc2a4745e48098b9da07139010290: Deleting log segment in path: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587518819-8548-0/minicluster-data/ts-0-root/wals/4e4dd15378b443c5b4fd56084d980bbb/wal-000000003 (ops 12-16)
I20260812 06:19:49.322948  8728 log.cc:1079] T 4e4dd15378b443c5b4fd56084d980bbb P 655bc2a4745e48098b9da07139010290: Deleting log segment in path: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587518819-8548-0/minicluster-data/ts-0-root/wals/4e4dd15378b443c5b4fd56084d980bbb/wal-000000004 (ops 17-21)
I20260812 06:19:49.322978  8728 log.cc:1079] T 4e4dd15378b443c5b4fd56084d980bbb P 655bc2a4745e48098b9da07139010290: Deleting log segment in path: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587518819-8548-0/minicluster-data/ts-0-root/wals/4e4dd15378b443c5b4fd56084d980bbb/wal-000000005 (ops 22-26)
I20260812 06:19:49.323010  8728 log.cc:1079] T 4e4dd15378b443c5b4fd56084d980bbb P 655bc2a4745e48098b9da07139010290: Deleting log segment in path: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587518819-8548-0/minicluster-data/ts-0-root/wals/4e4dd15378b443c5b4fd56084d980bbb/wal-000000006 (ops 27-31)
I20260812 06:19:49.323041  8728 log.cc:1079] T 4e4dd15378b443c5b4fd56084d980bbb P 655bc2a4745e48098b9da07139010290: Deleting log segment in path: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587518819-8548-0/minicluster-data/ts-0-root/wals/4e4dd15378b443c5b4fd56084d980bbb/wal-000000007 (ops 32-36)
I20260812 06:19:49.323072  8728 log.cc:1079] T 4e4dd15378b443c5b4fd56084d980bbb P 655bc2a4745e48098b9da07139010290: Deleting log segment in path: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587518819-8548-0/minicluster-data/ts-0-root/wals/4e4dd15378b443c5b4fd56084d980bbb/wal-000000008 (ops 37-40)
I20260812 06:19:49.323102  8728 log.cc:1079] T 4e4dd15378b443c5b4fd56084d980bbb P 655bc2a4745e48098b9da07139010290: Deleting log segment in path: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587518819-8548-0/minicluster-data/ts-0-root/wals/4e4dd15378b443c5b4fd56084d980bbb/wal-000000009 (ops 41-45)
I20260812 06:19:49.323132  8728 log.cc:1079] T 4e4dd15378b443c5b4fd56084d980bbb P 655bc2a4745e48098b9da07139010290: Deleting log segment in path: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587518819-8548-0/minicluster-data/ts-0-root/wals/4e4dd15378b443c5b4fd56084d980bbb/wal-000000010 (ops 46-50)
I20260812 06:19:49.323163  8728 log.cc:1079] T 4e4dd15378b443c5b4fd56084d980bbb P 655bc2a4745e48098b9da07139010290: Deleting log segment in path: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587518819-8548-0/minicluster-data/ts-0-root/wals/4e4dd15378b443c5b4fd56084d980bbb/wal-000000011 (ops 51-55)
I20260812 06:19:49.323194  8728 log.cc:1079] T 4e4dd15378b443c5b4fd56084d980bbb P 655bc2a4745e48098b9da07139010290: Deleting log segment in path: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587518819-8548-0/minicluster-data/ts-0-root/wals/4e4dd15378b443c5b4fd56084d980bbb/wal-000000012 (ops 56-60)
I20260812 06:19:49.323223  8728 log.cc:1079] T 4e4dd15378b443c5b4fd56084d980bbb P 655bc2a4745e48098b9da07139010290: Deleting log segment in path: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587518819-8548-0/minicluster-data/ts-0-root/wals/4e4dd15378b443c5b4fd56084d980bbb/wal-000000013 (ops 61-65)
I20260812 06:19:49.323254  8728 log.cc:1079] T 4e4dd15378b443c5b4fd56084d980bbb P 655bc2a4745e48098b9da07139010290: Deleting log segment in path: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587518819-8548-0/minicluster-data/ts-0-root/wals/4e4dd15378b443c5b4fd56084d980bbb/wal-000000014 (ops 66-70)
I20260812 06:19:49.345952  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: LogGCOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.023s	user 0.004s	sys 0.019s Metrics: {}
I20260812 06:19:49.346346  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb): perf score=3.181125
I20260812 06:19:49.364856  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.018s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4468,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:49.365317  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb): perf score=2.188937
I20260812 06:19:49.374223  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3410,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:49.374686  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling UndoDeltaBlockGCOp(4e4dd15378b443c5b4fd56084d980bbb): 472 bytes on disk
I20260812 06:19:49.375078  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: UndoDeltaBlockGCOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":44,"lbm_reads_lt_1ms":4}
I20260812 06:19:49.375571  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling MajorDeltaCompactionOp(4e4dd15378b443c5b4fd56084d980bbb): perf score=1.000000
I20260812 06:19:49.573937  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: MajorDeltaCompactionOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.198s	user 0.154s	sys 0.036s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918321,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":462,"lbm_read_time_us":13585,"lbm_reads_lt_1ms":674,"lbm_write_time_us":32623,"lbm_writes_lt_1ms":643,"mutex_wait_us":267,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":5632,"thread_start_us":93,"threads_started":1,"update_count":3000}
I20260812 06:19:49.574401  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb): perf score=14.095187
I20260812 06:19:49.635576  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.061s	user 0.022s	sys 0.036s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24301,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:49.636075  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb): perf score=2.188937
I20260812 06:19:49.647578  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.011s	user 0.004s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4281,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:49.647992  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling MajorDeltaCompactionOp(4e4dd15378b443c5b4fd56084d980bbb): perf score=1.000000
I20260812 06:19:49.823817  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: MajorDeltaCompactionOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.176s	user 0.106s	sys 0.059s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":613,"lbm_read_time_us":12641,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26912,"lbm_writes_lt_1ms":543,"mutex_wait_us":33,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2500}
I20260812 06:19:49.824317  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb): perf score=14.095187
I20260812 06:19:49.869241  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.045s	user 0.013s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":15794,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:49.869712  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb): perf score=2.188937
I20260812 06:19:49.887801  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.018s	user 0.002s	sys 0.014s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4237,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:49.888269  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling MajorDeltaCompactionOp(4e4dd15378b443c5b4fd56084d980bbb): perf score=1.000000
I20260812 06:19:50.065361  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: MajorDeltaCompactionOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.177s	user 0.086s	sys 0.077s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":4581,"lbm_read_time_us":11477,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28231,"lbm_writes_lt_1ms":543,"mutex_wait_us":3464,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:50.065860  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb): perf score=14.095187
I20260812 06:19:50.112566  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.047s	user 0.027s	sys 0.017s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":20806,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:50.113113  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb): perf score=2.188937
I20260812 06:19:50.124266  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.011s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3665,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:50.124899  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling MajorDeltaCompactionOp(4e4dd15378b443c5b4fd56084d980bbb): perf score=1.000000
I20260812 06:19:50.288110  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: MajorDeltaCompactionOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.163s	user 0.105s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815685,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":150,"lbm_read_time_us":10690,"lbm_reads_lt_1ms":568,"lbm_write_time_us":28317,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9344,"update_count":2500}
I20260812 06:19:50.288779  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb): perf score=11.118625
I20260812 06:19:50.324335  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.035s	user 0.024s	sys 0.007s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14459,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:50.324829  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb): perf score=2.188937
I20260812 06:19:50.341301  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.016s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5009,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:50.341867  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling MajorDeltaCompactionOp(4e4dd15378b443c5b4fd56084d980bbb): perf score=1.000000
I20260812 06:19:50.465698  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: MajorDeltaCompactionOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.124s	user 0.086s	sys 0.037s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713263,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":192,"lbm_read_time_us":7117,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24497,"lbm_writes_lt_1ms":443,"mutex_wait_us":38,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:50.466347  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb): perf score=10.126437
I20260812 06:19:50.508689  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.042s	user 0.020s	sys 0.018s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18201,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:50.509195  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb): perf score=2.188937
I20260812 06:19:50.520989  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4468,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:50.521456  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling MajorDeltaCompactionOp(4e4dd15378b443c5b4fd56084d980bbb): perf score=1.000000
I20260812 06:19:50.647187  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: MajorDeltaCompactionOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.126s	user 0.097s	sys 0.027s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":219,"lbm_read_time_us":10162,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24870,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3072,"update_count":2000}
I20260812 06:19:50.648012  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb): perf score=11.118625
I20260812 06:19:50.689970  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.042s	user 0.027s	sys 0.015s Metrics: {"bytes_written":12594660,"delete_count":0,"lbm_write_time_us":14758,"lbm_writes_lt_1ms":310,"reinsert_count":0,"update_count":1535}
I20260812 06:19:50.690670  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb): perf score=2.188937
I20260812 06:19:50.702615  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.012s	user 0.002s	sys 0.009s Metrics: {"bytes_written":3815484,"delete_count":0,"lbm_write_time_us":4691,"lbm_writes_lt_1ms":96,"reinsert_count":0,"update_count":465}
I20260812 06:19:50.703013  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling FlushMRSOp(4e4dd15378b443c5b4fd56084d980bbb): perf score=1.000000
I20260812 06:19:50.727824  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: FlushMRSOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.025s	user 0.023s	sys 0.000s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":73,"dirs.run_cpu_time_us":205,"dirs.run_wall_time_us":1125,"drs_written":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1349,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:50.728528  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling LogGCOp(4e4dd15378b443c5b4fd56084d980bbb): free 121006384 bytes of WAL
I20260812 06:19:50.728734  8728 log_reader.cc:385] T 4e4dd15378b443c5b4fd56084d980bbb: removed 12 log segments from log reader
I20260812 06:19:50.728776  8728 log.cc:1079] T 4e4dd15378b443c5b4fd56084d980bbb P 655bc2a4745e48098b9da07139010290: Deleting log segment in path: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587518819-8548-0/minicluster-data/ts-0-root/wals/4e4dd15378b443c5b4fd56084d980bbb/wal-000000015 (ops 71-75)
I20260812 06:19:50.728813  8728 log.cc:1079] T 4e4dd15378b443c5b4fd56084d980bbb P 655bc2a4745e48098b9da07139010290: Deleting log segment in path: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587518819-8548-0/minicluster-data/ts-0-root/wals/4e4dd15378b443c5b4fd56084d980bbb/wal-000000016 (ops 76-80)
I20260812 06:19:50.728847  8728 log.cc:1079] T 4e4dd15378b443c5b4fd56084d980bbb P 655bc2a4745e48098b9da07139010290: Deleting log segment in path: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587518819-8548-0/minicluster-data/ts-0-root/wals/4e4dd15378b443c5b4fd56084d980bbb/wal-000000017 (ops 81-85)
I20260812 06:19:50.728873  8728 log.cc:1079] T 4e4dd15378b443c5b4fd56084d980bbb P 655bc2a4745e48098b9da07139010290: Deleting log segment in path: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587518819-8548-0/minicluster-data/ts-0-root/wals/4e4dd15378b443c5b4fd56084d980bbb/wal-000000018 (ops 86-90)
I20260812 06:19:50.728904  8728 log.cc:1079] T 4e4dd15378b443c5b4fd56084d980bbb P 655bc2a4745e48098b9da07139010290: Deleting log segment in path: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587518819-8548-0/minicluster-data/ts-0-root/wals/4e4dd15378b443c5b4fd56084d980bbb/wal-000000019 (ops 91-95)
I20260812 06:19:50.728935  8728 log.cc:1079] T 4e4dd15378b443c5b4fd56084d980bbb P 655bc2a4745e48098b9da07139010290: Deleting log segment in path: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587518819-8548-0/minicluster-data/ts-0-root/wals/4e4dd15378b443c5b4fd56084d980bbb/wal-000000020 (ops 96-100)
I20260812 06:19:50.728965  8728 log.cc:1079] T 4e4dd15378b443c5b4fd56084d980bbb P 655bc2a4745e48098b9da07139010290: Deleting log segment in path: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587518819-8548-0/minicluster-data/ts-0-root/wals/4e4dd15378b443c5b4fd56084d980bbb/wal-000000021 (ops 101-105)
I20260812 06:19:50.728996  8728 log.cc:1079] T 4e4dd15378b443c5b4fd56084d980bbb P 655bc2a4745e48098b9da07139010290: Deleting log segment in path: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587518819-8548-0/minicluster-data/ts-0-root/wals/4e4dd15378b443c5b4fd56084d980bbb/wal-000000022 (ops 106-110)
I20260812 06:19:50.729027  8728 log.cc:1079] T 4e4dd15378b443c5b4fd56084d980bbb P 655bc2a4745e48098b9da07139010290: Deleting log segment in path: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587518819-8548-0/minicluster-data/ts-0-root/wals/4e4dd15378b443c5b4fd56084d980bbb/wal-000000023 (ops 111-114)
I20260812 06:19:50.729056  8728 log.cc:1079] T 4e4dd15378b443c5b4fd56084d980bbb P 655bc2a4745e48098b9da07139010290: Deleting log segment in path: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587518819-8548-0/minicluster-data/ts-0-root/wals/4e4dd15378b443c5b4fd56084d980bbb/wal-000000024 (ops 115-119)
I20260812 06:19:50.729086  8728 log.cc:1079] T 4e4dd15378b443c5b4fd56084d980bbb P 655bc2a4745e48098b9da07139010290: Deleting log segment in path: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587518819-8548-0/minicluster-data/ts-0-root/wals/4e4dd15378b443c5b4fd56084d980bbb/wal-000000025 (ops 120-124)
I20260812 06:19:50.729116  8728 log.cc:1079] T 4e4dd15378b443c5b4fd56084d980bbb P 655bc2a4745e48098b9da07139010290: Deleting log segment in path: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587518819-8548-0/minicluster-data/ts-0-root/wals/4e4dd15378b443c5b4fd56084d980bbb/wal-000000026 (ops 125-129)
I20260812 06:19:50.751588  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: LogGCOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.023s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:19:50.752074  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling UndoDeltaBlockGCOp(4e4dd15378b443c5b4fd56084d980bbb): 471 bytes on disk
I20260812 06:19:50.752522  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: UndoDeltaBlockGCOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4}
I20260812 06:19:50.753098  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb): perf score=3.181125
I20260812 06:19:50.767002  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.014s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4105,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:50.767372  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb): perf score=2.188937
I20260812 06:19:50.776525  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.009s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3327,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:50.776878  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling MajorDeltaCompactionOp(4e4dd15378b443c5b4fd56084d980bbb): perf score=1.000000
I20260812 06:19:50.965727  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: MajorDeltaCompactionOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.189s	user 0.119s	sys 0.067s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918316,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":3184,"lbm_read_time_us":12349,"lbm_reads_lt_1ms":674,"lbm_write_time_us":30186,"lbm_writes_lt_1ms":643,"mutex_wait_us":2343,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2048,"thread_start_us":96,"threads_started":1,"update_count":3000}
I20260812 06:19:50.967289  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb): perf score=14.095187
I20260812 06:19:51.007556  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.040s	user 0.019s	sys 0.019s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":17834,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:51.008098  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb): perf score=2.188937
I20260812 06:19:51.019239  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4300,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:51.019807  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling MajorDeltaCompactionOp(4e4dd15378b443c5b4fd56084d980bbb): perf score=1.000000
I20260812 06:19:51.179299  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: MajorDeltaCompactionOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.159s	user 0.109s	sys 0.050s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":610,"lbm_read_time_us":12285,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25415,"lbm_writes_lt_1ms":543,"mutex_wait_us":36,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4736,"update_count":2500}
I20260812 06:19:51.179842  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb): perf score=14.095187
I20260812 06:19:51.237809  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.058s	user 0.021s	sys 0.032s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21397,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:51.238373  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb): perf score=2.188937
I20260812 06:19:51.253149  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5710,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:51.253610  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling MajorDeltaCompactionOp(4e4dd15378b443c5b4fd56084d980bbb): perf score=1.000000
I20260812 06:19:51.417820  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: MajorDeltaCompactionOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.164s	user 0.116s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":851,"lbm_read_time_us":12769,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28441,"lbm_writes_lt_1ms":543,"mutex_wait_us":296,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":29952,"update_count":2500}
I20260812 06:19:51.418339  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb): perf score=11.118625
I20260812 06:19:51.452175  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.034s	user 0.024s	sys 0.007s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14667,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:51.452730  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb): perf score=2.188937
I20260812 06:19:51.472455  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.020s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4510,"lbm_writes_lt_1ms":93,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":450}
I20260812 06:19:51.473074  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling MajorDeltaCompactionOp(4e4dd15378b443c5b4fd56084d980bbb): perf score=1.000000
I20260812 06:19:51.617231  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: MajorDeltaCompactionOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.144s	user 0.096s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713263,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":656,"lbm_read_time_us":10968,"lbm_reads_lt_1ms":464,"lbm_write_time_us":22397,"lbm_writes_lt_1ms":443,"mutex_wait_us":52,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2000}
I20260812 06:19:51.617762  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb): perf score=10.126437
I20260812 06:19:51.645819  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.028s	user 0.018s	sys 0.007s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":12763,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:51.646298  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb): perf score=2.188937
I20260812 06:19:51.663940  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.017s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5151,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:51.664533  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling MajorDeltaCompactionOp(4e4dd15378b443c5b4fd56084d980bbb): perf score=1.000000
I20260812 06:19:51.776870  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: MajorDeltaCompactionOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.112s	user 0.091s	sys 0.018s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713273,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":124,"lbm_read_time_us":7377,"lbm_reads_lt_1ms":464,"lbm_write_time_us":22171,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:51.777472  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb): perf score=10.126437
I20260812 06:19:51.810804  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.033s	user 0.021s	sys 0.008s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":13138,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:51.811231  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb): perf score=2.188937
I20260812 06:19:51.821795  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4135,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:51.822399  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling MajorDeltaCompactionOp(4e4dd15378b443c5b4fd56084d980bbb): perf score=1.000000
I20260812 06:19:51.942335  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: MajorDeltaCompactionOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.120s	user 0.110s	sys 0.008s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713271,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":535,"lbm_read_time_us":8572,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23608,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7168,"update_count":2000}
I20260812 06:19:51.942950  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb): perf score=10.126437
I20260812 06:19:51.986680  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.044s	user 0.023s	sys 0.019s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":14935,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:51.987242  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb): perf score=2.188937
I20260812 06:19:52.002229  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.015s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5703,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:52.002707  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling MajorDeltaCompactionOp(4e4dd15378b443c5b4fd56084d980bbb): perf score=1.000000
I20260812 06:19:52.141628  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: MajorDeltaCompactionOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.139s	user 0.103s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713271,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":6387,"lbm_read_time_us":10300,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23371,"lbm_writes_lt_1ms":443,"mutex_wait_us":3072,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5504,"update_count":2000}
I20260812 06:19:52.142189  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb): perf score=10.126437
I20260812 06:19:52.180024  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.038s	user 0.015s	sys 0.014s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":13677,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:52.180532  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb): perf score=2.188937
I20260812 06:19:52.195250  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5503,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:52.195760  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling FlushMRSOp(4e4dd15378b443c5b4fd56084d980bbb): perf score=1.000000
I20260812 06:19:52.224500  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: FlushMRSOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.029s	user 0.023s	sys 0.003s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":59,"dirs.run_cpu_time_us":199,"dirs.run_wall_time_us":1112,"drs_written":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1876,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:52.225253  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling LogGCOp(4e4dd15378b443c5b4fd56084d980bbb): free 133477766 bytes of WAL
I20260812 06:19:52.225486  8728 log_reader.cc:385] T 4e4dd15378b443c5b4fd56084d980bbb: removed 13 log segments from log reader
I20260812 06:19:52.225548  8728 log.cc:1079] T 4e4dd15378b443c5b4fd56084d980bbb P 655bc2a4745e48098b9da07139010290: Deleting log segment in path: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587518819-8548-0/minicluster-data/ts-0-root/wals/4e4dd15378b443c5b4fd56084d980bbb/wal-000000027 (ops 130-134)
I20260812 06:19:52.225590  8728 log.cc:1079] T 4e4dd15378b443c5b4fd56084d980bbb P 655bc2a4745e48098b9da07139010290: Deleting log segment in path: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587518819-8548-0/minicluster-data/ts-0-root/wals/4e4dd15378b443c5b4fd56084d980bbb/wal-000000028 (ops 135-139)
I20260812 06:19:52.225620  8728 log.cc:1079] T 4e4dd15378b443c5b4fd56084d980bbb P 655bc2a4745e48098b9da07139010290: Deleting log segment in path: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587518819-8548-0/minicluster-data/ts-0-root/wals/4e4dd15378b443c5b4fd56084d980bbb/wal-000000029 (ops 140-144)
I20260812 06:19:52.225644  8728 log.cc:1079] T 4e4dd15378b443c5b4fd56084d980bbb P 655bc2a4745e48098b9da07139010290: Deleting log segment in path: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587518819-8548-0/minicluster-data/ts-0-root/wals/4e4dd15378b443c5b4fd56084d980bbb/wal-000000030 (ops 145-149)
I20260812 06:19:52.225675  8728 log.cc:1079] T 4e4dd15378b443c5b4fd56084d980bbb P 655bc2a4745e48098b9da07139010290: Deleting log segment in path: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587518819-8548-0/minicluster-data/ts-0-root/wals/4e4dd15378b443c5b4fd56084d980bbb/wal-000000031 (ops 150-154)
I20260812 06:19:52.225705  8728 log.cc:1079] T 4e4dd15378b443c5b4fd56084d980bbb P 655bc2a4745e48098b9da07139010290: Deleting log segment in path: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587518819-8548-0/minicluster-data/ts-0-root/wals/4e4dd15378b443c5b4fd56084d980bbb/wal-000000032 (ops 155-159)
I20260812 06:19:52.225732  8728 log.cc:1079] T 4e4dd15378b443c5b4fd56084d980bbb P 655bc2a4745e48098b9da07139010290: Deleting log segment in path: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587518819-8548-0/minicluster-data/ts-0-root/wals/4e4dd15378b443c5b4fd56084d980bbb/wal-000000033 (ops 160-164)
I20260812 06:19:52.225760  8728 log.cc:1079] T 4e4dd15378b443c5b4fd56084d980bbb P 655bc2a4745e48098b9da07139010290: Deleting log segment in path: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587518819-8548-0/minicluster-data/ts-0-root/wals/4e4dd15378b443c5b4fd56084d980bbb/wal-000000034 (ops 165-169)
I20260812 06:19:52.225790  8728 log.cc:1079] T 4e4dd15378b443c5b4fd56084d980bbb P 655bc2a4745e48098b9da07139010290: Deleting log segment in path: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587518819-8548-0/minicluster-data/ts-0-root/wals/4e4dd15378b443c5b4fd56084d980bbb/wal-000000035 (ops 170-174)
I20260812 06:19:52.225821  8728 log.cc:1079] T 4e4dd15378b443c5b4fd56084d980bbb P 655bc2a4745e48098b9da07139010290: Deleting log segment in path: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587518819-8548-0/minicluster-data/ts-0-root/wals/4e4dd15378b443c5b4fd56084d980bbb/wal-000000036 (ops 175-179)
I20260812 06:19:52.225852  8728 log.cc:1079] T 4e4dd15378b443c5b4fd56084d980bbb P 655bc2a4745e48098b9da07139010290: Deleting log segment in path: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587518819-8548-0/minicluster-data/ts-0-root/wals/4e4dd15378b443c5b4fd56084d980bbb/wal-000000037 (ops 180-184)
I20260812 06:19:52.225879  8728 log.cc:1079] T 4e4dd15378b443c5b4fd56084d980bbb P 655bc2a4745e48098b9da07139010290: Deleting log segment in path: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587518819-8548-0/minicluster-data/ts-0-root/wals/4e4dd15378b443c5b4fd56084d980bbb/wal-000000038 (ops 185-189)
I20260812 06:19:52.225932  8728 log.cc:1079] T 4e4dd15378b443c5b4fd56084d980bbb P 655bc2a4745e48098b9da07139010290: Deleting log segment in path: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587518819-8548-0/minicluster-data/ts-0-root/wals/4e4dd15378b443c5b4fd56084d980bbb/wal-000000039 (ops 190-194)
I20260812 06:19:52.252628  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: LogGCOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.027s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:19:52.253001  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling UndoDeltaBlockGCOp(4e4dd15378b443c5b4fd56084d980bbb): 483 bytes on disk
I20260812 06:19:52.253428  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: UndoDeltaBlockGCOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4}
I20260812 06:19:52.253980  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb): perf score=3.181125
I20260812 06:19:52.266418  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.012s	user 0.007s	sys 0.005s Metrics: {"bytes_written":5210311,"delete_count":0,"lbm_write_time_us":5086,"lbm_writes_lt_1ms":130,"reinsert_count":0,"update_count":635}
I20260812 06:19:52.266794  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb): perf score=1.196750
I20260812 06:19:52.282609  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.016s	user 0.004s	sys 0.011s Metrics: {"bytes_written":2994980,"delete_count":0,"lbm_write_time_us":2804,"lbm_writes_lt_1ms":76,"reinsert_count":0,"update_count":365}
I20260812 06:19:52.286175  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling MajorDeltaCompactionOp(4e4dd15378b443c5b4fd56084d980bbb): perf score=1.000000
I20260812 06:19:52.381707  8548 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.612s	user 1.678s	sys 0.136s
I20260812 06:19:52.470666  8548 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.088s	user 0.000s	sys 0.003s
I20260812 06:19:52.471338  8548 tablet_server.cc:179] TabletServer@127.8.89.1:0 shutting down...
I20260812 06:19:52.474813  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: MajorDeltaCompactionOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.188s	user 0.118s	sys 0.069s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918309,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1468,"lbm_read_time_us":14565,"lbm_reads_lt_1ms":670,"lbm_write_time_us":29326,"lbm_writes_lt_1ms":643,"mutex_wait_us":43,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":12032,"thread_start_us":67,"threads_started":1,"update_count":3000}
I20260812 06:19:52.475370  8830 maintenance_manager.cc:419] P 655bc2a4745e48098b9da07139010290: Scheduling FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb): perf score=6.157687
I20260812 06:19:52.495648  8728 maintenance_manager.cc:643] P 655bc2a4745e48098b9da07139010290: FlushDeltaMemStoresOp(4e4dd15378b443c5b4fd56084d980bbb) complete. Timing: real 0.020s	user 0.013s	sys 0.004s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":8312,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:19:52.496202  8548 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:52.496573  8548 tablet_replica.cc:333] T 4e4dd15378b443c5b4fd56084d980bbb P 655bc2a4745e48098b9da07139010290: stopping tablet replica
I20260812 06:19:52.496793  8548 raft_consensus.cc:2243] T 4e4dd15378b443c5b4fd56084d980bbb P 655bc2a4745e48098b9da07139010290 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:52.497018  8548 raft_consensus.cc:2272] T 4e4dd15378b443c5b4fd56084d980bbb P 655bc2a4745e48098b9da07139010290 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:52.511523  8548 tablet_server.cc:196] TabletServer@127.8.89.1:0 shutdown complete.
I20260812 06:19:52.524847  8548 master.cc:562] Master@127.8.89.62:33429 shutting down...
I20260812 06:19:52.527989  8548 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 9b060c2c9e964c8f9a9a6a21fdc00eda [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:52.528147  8548 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 9b060c2c9e964c8f9a9a6a21fdc00eda [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:52.528216  8548 tablet_replica.cc:333] T 00000000000000000000000000000000 P 9b060c2c9e964c8f9a9a6a21fdc00eda: stopping tablet replica
I20260812 06:19:52.540210  8548 master.cc:584] Master@127.8.89.62:33429 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5082 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:19:52.622776  8548 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.8.89.62:38873
I20260812 06:19:52.623172  8548 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:52.625031  8894 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:52.625058  8887 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:52.625126  8889 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:52.625128  8548 server_base.cc:1061] running on GCE node
I20260812 06:19:52.625394  8548 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:52.625443  8548 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:52.625464  8548 hybrid_clock.cc:648] HybridClock initialized: now 1786515592625464 us; error 0 us; skew 500 ppm
I20260812 06:19:52.626245  8548 webserver.cc:533] Webserver started at http://127.8.89.62:40089/ using document root <none> and password file <none>
I20260812 06:19:52.626387  8548 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:52.626430  8548 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:52.626505  8548 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:52.626858  8548 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587518819-8548-0/minicluster-data/master-0-root/instance:
uuid: "42aa5efd7dc54b5e83c5e6cd9bb91ad3"
format_stamp: "Formatted at 2026-08-12 06:19:52 on dist-test-slave-tc2s"
I20260812 06:19:52.628223  8548 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:52.629050  8901 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:52.629241  8548 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:52.629311  8548 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587518819-8548-0/minicluster-data/master-0-root
uuid: "42aa5efd7dc54b5e83c5e6cd9bb91ad3"
format_stamp: "Formatted at 2026-08-12 06:19:52 on dist-test-slave-tc2s"
I20260812 06:19:52.629377  8548 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587518819-8548-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587518819-8548-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587518819-8548-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:52.637784  8548 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:52.638119  8548 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:52.641983  8548 rpc_server.cc:307] RPC server started. Bound to: 127.8.89.62:38873
I20260812 06:19:52.647258  8993 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.8.89.62:38873 every 8 connection(s)
I20260812 06:19:52.647751  8995 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:52.649423  8995 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 42aa5efd7dc54b5e83c5e6cd9bb91ad3: Bootstrap starting.
I20260812 06:19:52.650182  8995 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 42aa5efd7dc54b5e83c5e6cd9bb91ad3: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:52.651057  8995 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 42aa5efd7dc54b5e83c5e6cd9bb91ad3: No bootstrap required, opened a new log
I20260812 06:19:52.651417  8995 raft_consensus.cc:359] T 00000000000000000000000000000000 P 42aa5efd7dc54b5e83c5e6cd9bb91ad3 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "42aa5efd7dc54b5e83c5e6cd9bb91ad3" member_type: VOTER }
I20260812 06:19:52.651499  8995 raft_consensus.cc:385] T 00000000000000000000000000000000 P 42aa5efd7dc54b5e83c5e6cd9bb91ad3 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:52.651528  8995 raft_consensus.cc:740] T 00000000000000000000000000000000 P 42aa5efd7dc54b5e83c5e6cd9bb91ad3 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 42aa5efd7dc54b5e83c5e6cd9bb91ad3, State: Initialized, Role: FOLLOWER
I20260812 06:19:52.651667  8995 consensus_queue.cc:260] T 00000000000000000000000000000000 P 42aa5efd7dc54b5e83c5e6cd9bb91ad3 [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: "42aa5efd7dc54b5e83c5e6cd9bb91ad3" member_type: VOTER }
I20260812 06:19:52.651751  8995 raft_consensus.cc:399] T 00000000000000000000000000000000 P 42aa5efd7dc54b5e83c5e6cd9bb91ad3 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:52.651791  8995 raft_consensus.cc:493] T 00000000000000000000000000000000 P 42aa5efd7dc54b5e83c5e6cd9bb91ad3 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:52.651839  8995 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 42aa5efd7dc54b5e83c5e6cd9bb91ad3 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:52.652480  8995 raft_consensus.cc:515] T 00000000000000000000000000000000 P 42aa5efd7dc54b5e83c5e6cd9bb91ad3 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "42aa5efd7dc54b5e83c5e6cd9bb91ad3" member_type: VOTER }
I20260812 06:19:52.652604  8995 leader_election.cc:304] T 00000000000000000000000000000000 P 42aa5efd7dc54b5e83c5e6cd9bb91ad3 [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: 42aa5efd7dc54b5e83c5e6cd9bb91ad3; no voters: 
I20260812 06:19:52.652765  8995 leader_election.cc:290] T 00000000000000000000000000000000 P 42aa5efd7dc54b5e83c5e6cd9bb91ad3 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:52.652874  9003 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 42aa5efd7dc54b5e83c5e6cd9bb91ad3 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:52.653082  9003 raft_consensus.cc:697] T 00000000000000000000000000000000 P 42aa5efd7dc54b5e83c5e6cd9bb91ad3 [term 1 LEADER]: Becoming Leader. State: Replica: 42aa5efd7dc54b5e83c5e6cd9bb91ad3, State: Running, Role: LEADER
I20260812 06:19:52.653165  8995 sys_catalog.cc:565] T 00000000000000000000000000000000 P 42aa5efd7dc54b5e83c5e6cd9bb91ad3 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:52.653215  9003 consensus_queue.cc:237] T 00000000000000000000000000000000 P 42aa5efd7dc54b5e83c5e6cd9bb91ad3 [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: "42aa5efd7dc54b5e83c5e6cd9bb91ad3" member_type: VOTER }
I20260812 06:19:52.653671  9004 sys_catalog.cc:455] T 00000000000000000000000000000000 P 42aa5efd7dc54b5e83c5e6cd9bb91ad3 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "42aa5efd7dc54b5e83c5e6cd9bb91ad3" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "42aa5efd7dc54b5e83c5e6cd9bb91ad3" member_type: VOTER } }
I20260812 06:19:52.653769  9004 sys_catalog.cc:458] T 00000000000000000000000000000000 P 42aa5efd7dc54b5e83c5e6cd9bb91ad3 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:52.653956  9008 sys_catalog.cc:455] T 00000000000000000000000000000000 P 42aa5efd7dc54b5e83c5e6cd9bb91ad3 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 42aa5efd7dc54b5e83c5e6cd9bb91ad3. Latest consensus state: current_term: 1 leader_uuid: "42aa5efd7dc54b5e83c5e6cd9bb91ad3" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "42aa5efd7dc54b5e83c5e6cd9bb91ad3" member_type: VOTER } }
I20260812 06:19:52.654099  9008 sys_catalog.cc:458] T 00000000000000000000000000000000 P 42aa5efd7dc54b5e83c5e6cd9bb91ad3 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:52.654029  9016 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:52.654959  9016 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:52.655098  8548 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:52.656814  9016 catalog_manager.cc:1383] Generated new cluster ID: ad907982a78444aa96cbd24f72ec859c
I20260812 06:19:52.656867  9016 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:52.671873  9016 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:52.672374  9016 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:52.679062  9016 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 42aa5efd7dc54b5e83c5e6cd9bb91ad3: Generated new TSK 0
I20260812 06:19:52.679203  9016 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:52.687070  8548 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:52.688732  9034 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:52.688771  9036 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:19:52.688797  9038 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:52.688959  8548 server_base.cc:1061] running on GCE node
I20260812 06:19:52.689132  8548 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:52.689164  8548 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:52.689177  8548 hybrid_clock.cc:648] HybridClock initialized: now 1786515592689178 us; error 0 us; skew 500 ppm
I20260812 06:19:52.689880  8548 webserver.cc:533] Webserver started at http://127.8.89.1:36437/ using document root <none> and password file <none>
I20260812 06:19:52.690042  8548 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:52.690086  8548 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:52.690137  8548 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:52.690439  8548 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587518819-8548-0/minicluster-data/ts-0-root/instance:
uuid: "a72188cff32f43f7ad0b0bdc77ce5589"
format_stamp: "Formatted at 2026-08-12 06:19:52 on dist-test-slave-tc2s"
I20260812 06:19:52.691716  8548 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:19:52.692626  9045 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:52.692840  8548 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:19:52.692912  8548 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587518819-8548-0/minicluster-data/ts-0-root
uuid: "a72188cff32f43f7ad0b0bdc77ce5589"
format_stamp: "Formatted at 2026-08-12 06:19:52 on dist-test-slave-tc2s"
I20260812 06:19:52.692976  8548 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587518819-8548-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587518819-8548-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587518819-8548-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:52.707787  8548 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:52.708089  8548 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:52.708330  8548 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:52.708725  8548 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:52.708762  8548 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:52.708803  8548 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:52.708830  8548 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:52.712694  8548 rpc_server.cc:307] RPC server started. Bound to: 127.8.89.1:43663
I20260812 06:19:52.712744  9157 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.8.89.1:43663 every 8 connection(s)
I20260812 06:19:52.720100  9159 heartbeater.cc:344] Connected to a master server at 127.8.89.62:38873
I20260812 06:19:52.720198  9159 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:52.720412  9159 heartbeater.cc:507] Master 127.8.89.62:38873 requested a full tablet report, sending...
I20260812 06:19:52.720985  8932 ts_manager.cc:194] Registered new tserver with Master: a72188cff32f43f7ad0b0bdc77ce5589 (127.8.89.1:43663)
I20260812 06:19:52.721648  8932 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:47462
I20260812 06:19:52.721872  8548 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.008797924s
I20260812 06:19:52.728029  8932 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:47464:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:52.735869  9088 tablet_service.cc:1511] Processing CreateTablet for tablet 3b090fb666cb4a48a7b20ce1a96b6691 (DEFAULT_TABLE table=heavy-update-compaction-test [id=1898c3b5cd2e4323ac0adeaf1f138bf9]), partition=
I20260812 06:19:52.736097  9088 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 3b090fb666cb4a48a7b20ce1a96b6691. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:52.737795  9178 tablet_bootstrap.cc:492] T 3b090fb666cb4a48a7b20ce1a96b6691 P a72188cff32f43f7ad0b0bdc77ce5589: Bootstrap starting.
I20260812 06:19:52.738761  9178 tablet_bootstrap.cc:654] T 3b090fb666cb4a48a7b20ce1a96b6691 P a72188cff32f43f7ad0b0bdc77ce5589: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:52.739687  9178 tablet_bootstrap.cc:492] T 3b090fb666cb4a48a7b20ce1a96b6691 P a72188cff32f43f7ad0b0bdc77ce5589: No bootstrap required, opened a new log
I20260812 06:19:52.739758  9178 ts_tablet_manager.cc:1403] T 3b090fb666cb4a48a7b20ce1a96b6691 P a72188cff32f43f7ad0b0bdc77ce5589: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:19:52.740121  9178 raft_consensus.cc:359] T 3b090fb666cb4a48a7b20ce1a96b6691 P a72188cff32f43f7ad0b0bdc77ce5589 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a72188cff32f43f7ad0b0bdc77ce5589" member_type: VOTER last_known_addr { host: "127.8.89.1" port: 43663 } }
I20260812 06:19:52.740199  9178 raft_consensus.cc:385] T 3b090fb666cb4a48a7b20ce1a96b6691 P a72188cff32f43f7ad0b0bdc77ce5589 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:52.740232  9178 raft_consensus.cc:740] T 3b090fb666cb4a48a7b20ce1a96b6691 P a72188cff32f43f7ad0b0bdc77ce5589 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: a72188cff32f43f7ad0b0bdc77ce5589, State: Initialized, Role: FOLLOWER
I20260812 06:19:52.740491  9178 consensus_queue.cc:260] T 3b090fb666cb4a48a7b20ce1a96b6691 P a72188cff32f43f7ad0b0bdc77ce5589 [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: "a72188cff32f43f7ad0b0bdc77ce5589" member_type: VOTER last_known_addr { host: "127.8.89.1" port: 43663 } }
I20260812 06:19:52.740581  9181 raft_consensus.cc:493] T 3b090fb666cb4a48a7b20ce1a96b6691 P a72188cff32f43f7ad0b0bdc77ce5589 [term 0 FOLLOWER]: Starting pre-election (no leader contacted us within the election timeout)
I20260812 06:19:52.740666  9181 raft_consensus.cc:515] T 3b090fb666cb4a48a7b20ce1a96b6691 P a72188cff32f43f7ad0b0bdc77ce5589 [term 0 FOLLOWER]: Starting pre-election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a72188cff32f43f7ad0b0bdc77ce5589" member_type: VOTER last_known_addr { host: "127.8.89.1" port: 43663 } }
I20260812 06:19:52.740814  9181 leader_election.cc:304] T 3b090fb666cb4a48a7b20ce1a96b6691 P a72188cff32f43f7ad0b0bdc77ce5589 [CANDIDATE]: Term 1 pre-election: Election decided. Result: candidate won. Election summary: received 1 responses out of 1 voters: 1 yes votes; 0 no votes. yes voters: a72188cff32f43f7ad0b0bdc77ce5589; no voters: 
I20260812 06:19:52.740828  9178 raft_consensus.cc:399] T 3b090fb666cb4a48a7b20ce1a96b6691 P a72188cff32f43f7ad0b0bdc77ce5589 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:52.740880  9178 raft_consensus.cc:493] T 3b090fb666cb4a48a7b20ce1a96b6691 P a72188cff32f43f7ad0b0bdc77ce5589 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:52.740923  9178 raft_consensus.cc:3060] T 3b090fb666cb4a48a7b20ce1a96b6691 P a72188cff32f43f7ad0b0bdc77ce5589 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:52.741005  9181 leader_election.cc:290] T 3b090fb666cb4a48a7b20ce1a96b6691 P a72188cff32f43f7ad0b0bdc77ce5589 [CANDIDATE]: Term 1 pre-election: Requested pre-vote from peers 
I20260812 06:19:52.741756  9178 raft_consensus.cc:515] T 3b090fb666cb4a48a7b20ce1a96b6691 P a72188cff32f43f7ad0b0bdc77ce5589 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a72188cff32f43f7ad0b0bdc77ce5589" member_type: VOTER last_known_addr { host: "127.8.89.1" port: 43663 } }
I20260812 06:19:52.741868  9178 leader_election.cc:304] T 3b090fb666cb4a48a7b20ce1a96b6691 P a72188cff32f43f7ad0b0bdc77ce5589 [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: a72188cff32f43f7ad0b0bdc77ce5589; no voters: 
I20260812 06:19:52.741959  9178 leader_election.cc:290] T 3b090fb666cb4a48a7b20ce1a96b6691 P a72188cff32f43f7ad0b0bdc77ce5589 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:52.741959  9181 raft_consensus.cc:2764] T 3b090fb666cb4a48a7b20ce1a96b6691 P a72188cff32f43f7ad0b0bdc77ce5589 [term 1 FOLLOWER]: Leader pre-election decision vote started in defunct term 0: won
I20260812 06:19:52.742123  9181 raft_consensus.cc:2804] T 3b090fb666cb4a48a7b20ce1a96b6691 P a72188cff32f43f7ad0b0bdc77ce5589 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:52.742228  9181 raft_consensus.cc:697] T 3b090fb666cb4a48a7b20ce1a96b6691 P a72188cff32f43f7ad0b0bdc77ce5589 [term 1 LEADER]: Becoming Leader. State: Replica: a72188cff32f43f7ad0b0bdc77ce5589, State: Running, Role: LEADER
I20260812 06:19:52.742266  9178 ts_tablet_manager.cc:1434] T 3b090fb666cb4a48a7b20ce1a96b6691 P a72188cff32f43f7ad0b0bdc77ce5589: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:19:52.742302  9159 heartbeater.cc:499] Master 127.8.89.62:38873 was elected leader, sending a full tablet report...
I20260812 06:19:52.742383  9181 consensus_queue.cc:237] T 3b090fb666cb4a48a7b20ce1a96b6691 P a72188cff32f43f7ad0b0bdc77ce5589 [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: "a72188cff32f43f7ad0b0bdc77ce5589" member_type: VOTER last_known_addr { host: "127.8.89.1" port: 43663 } }
I20260812 06:19:52.743590  8932 catalog_manager.cc:5719] T 3b090fb666cb4a48a7b20ce1a96b6691 P a72188cff32f43f7ad0b0bdc77ce5589 reported cstate change: term changed from 0 to 1, leader changed from <none> to a72188cff32f43f7ad0b0bdc77ce5589 (127.8.89.1). New cstate: current_term: 1 leader_uuid: "a72188cff32f43f7ad0b0bdc77ce5589" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a72188cff32f43f7ad0b0bdc77ce5589" member_type: VOTER last_known_addr { host: "127.8.89.1" port: 43663 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:52.796491  8548 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.050s	user 0.012s	sys 0.009s
I20260812 06:19:52.963601  9160 maintenance_manager.cc:419] P a72188cff32f43f7ad0b0bdc77ce5589: Scheduling FlushMRSOp(3b090fb666cb4a48a7b20ce1a96b6691): perf score=23.023690
I20260812 06:19:53.134335  9051 maintenance_manager.cc:643] P a72188cff32f43f7ad0b0bdc77ce5589: FlushMRSOp(3b090fb666cb4a48a7b20ce1a96b6691) complete. Timing: real 0.170s	user 0.142s	sys 0.028s Metrics: {"bytes_written":12717736,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":57,"dirs.run_cpu_time_us":203,"dirs.run_wall_time_us":917,"drs_written":1,"lbm_read_time_us":68,"lbm_reads_lt_1ms":4,"lbm_write_time_us":42499,"lbm_writes_lt_1ms":867,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"spinlock_wait_cycles":3072,"update_count":1550}
I20260812 06:19:53.135133  9160 maintenance_manager.cc:419] P a72188cff32f43f7ad0b0bdc77ce5589: Scheduling LogGCOp(3b090fb666cb4a48a7b20ce1a96b6691): free 20743880 bytes of WAL
I20260812 06:19:53.135406  9051 log_reader.cc:385] T 3b090fb666cb4a48a7b20ce1a96b6691: removed 2 log segments from log reader
I20260812 06:19:53.135476  9051 log.cc:1079] T 3b090fb666cb4a48a7b20ce1a96b6691 P a72188cff32f43f7ad0b0bdc77ce5589: Deleting log segment in path: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587518819-8548-0/minicluster-data/ts-0-root/wals/3b090fb666cb4a48a7b20ce1a96b6691/wal-000000001 (ops 1-6)
I20260812 06:19:53.135527  9051 log.cc:1079] T 3b090fb666cb4a48a7b20ce1a96b6691 P a72188cff32f43f7ad0b0bdc77ce5589: Deleting log segment in path: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587518819-8548-0/minicluster-data/ts-0-root/wals/3b090fb666cb4a48a7b20ce1a96b6691/wal-000000002 (ops 7-11)
I20260812 06:19:53.141078  9051 maintenance_manager.cc:643] P a72188cff32f43f7ad0b0bdc77ce5589: LogGCOp(3b090fb666cb4a48a7b20ce1a96b6691) complete. Timing: real 0.006s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:19:53.141547  9160 maintenance_manager.cc:419] P a72188cff32f43f7ad0b0bdc77ce5589: Scheduling FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691): perf score=2.188937
I20260812 06:19:53.155864  9051 maintenance_manager.cc:643] P a72188cff32f43f7ad0b0bdc77ce5589: FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691) complete. Timing: real 0.014s	user 0.004s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4560,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:53.156407  9160 maintenance_manager.cc:419] P a72188cff32f43f7ad0b0bdc77ce5589: Scheduling UndoDeltaBlockGCOp(3b090fb666cb4a48a7b20ce1a96b6691): 20513814 bytes on disk
I20260812 06:19:53.156810  9051 maintenance_manager.cc:643] P a72188cff32f43f7ad0b0bdc77ce5589: UndoDeltaBlockGCOp(3b090fb666cb4a48a7b20ce1a96b6691) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4}
I20260812 06:19:53.157210  9160 maintenance_manager.cc:419] P a72188cff32f43f7ad0b0bdc77ce5589: Scheduling MajorDeltaCompactionOp(3b090fb666cb4a48a7b20ce1a96b6691): perf score=1.000000
I20260812 06:19:53.311672  9051 maintenance_manager.cc:643] P a72188cff32f43f7ad0b0bdc77ce5589: MajorDeltaCompactionOp(3b090fb666cb4a48a7b20ce1a96b6691) complete. Timing: real 0.154s	user 0.107s	sys 0.044s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713264,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":474,"lbm_read_time_us":11402,"lbm_reads_lt_1ms":464,"lbm_write_time_us":22187,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"thread_start_us":284,"threads_started":5,"update_count":2000}
I20260812 06:19:53.312189  9160 maintenance_manager.cc:419] P a72188cff32f43f7ad0b0bdc77ce5589: Scheduling FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691): perf score=14.095187
I20260812 06:19:53.364986  9051 maintenance_manager.cc:643] P a72188cff32f43f7ad0b0bdc77ce5589: FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691) complete. Timing: real 0.053s	user 0.020s	sys 0.025s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17233,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:53.365424  9160 maintenance_manager.cc:419] P a72188cff32f43f7ad0b0bdc77ce5589: Scheduling FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691): perf score=2.188937
I20260812 06:19:53.375283  9051 maintenance_manager.cc:643] P a72188cff32f43f7ad0b0bdc77ce5589: FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691) complete. Timing: real 0.010s	user 0.005s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3940,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:53.375633  9160 maintenance_manager.cc:419] P a72188cff32f43f7ad0b0bdc77ce5589: Scheduling MajorDeltaCompactionOp(3b090fb666cb4a48a7b20ce1a96b6691): perf score=1.000000
I20260812 06:19:53.554199  9051 maintenance_manager.cc:643] P a72188cff32f43f7ad0b0bdc77ce5589: MajorDeltaCompactionOp(3b090fb666cb4a48a7b20ce1a96b6691) complete. Timing: real 0.178s	user 0.132s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":740,"lbm_read_time_us":13100,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27263,"lbm_writes_lt_1ms":543,"mutex_wait_us":305,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2500}
I20260812 06:19:53.554718  9160 maintenance_manager.cc:419] P a72188cff32f43f7ad0b0bdc77ce5589: Scheduling FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691): perf score=11.118625
I20260812 06:19:53.582551  9051 maintenance_manager.cc:643] P a72188cff32f43f7ad0b0bdc77ce5589: FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691) complete. Timing: real 0.028s	user 0.023s	sys 0.004s Metrics: {"bytes_written":12717738,"delete_count":0,"lbm_write_time_us":11723,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:53.583137  9160 maintenance_manager.cc:419] P a72188cff32f43f7ad0b0bdc77ce5589: Scheduling FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691): perf score=2.188937
I20260812 06:19:53.598227  9051 maintenance_manager.cc:643] P a72188cff32f43f7ad0b0bdc77ce5589: FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691) complete. Timing: real 0.015s	user 0.002s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3844,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:53.598771  9160 maintenance_manager.cc:419] P a72188cff32f43f7ad0b0bdc77ce5589: Scheduling MajorDeltaCompactionOp(3b090fb666cb4a48a7b20ce1a96b6691): perf score=1.000000
I20260812 06:19:53.765136  9051 maintenance_manager.cc:643] P a72188cff32f43f7ad0b0bdc77ce5589: MajorDeltaCompactionOp(3b090fb666cb4a48a7b20ce1a96b6691) complete. Timing: real 0.166s	user 0.089s	sys 0.060s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713266,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":761,"lbm_read_time_us":10399,"lbm_reads_lt_1ms":464,"lbm_write_time_us":21474,"lbm_writes_lt_1ms":443,"mutex_wait_us":248,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6400,"update_count":2000}
I20260812 06:19:53.765700  9160 maintenance_manager.cc:419] P a72188cff32f43f7ad0b0bdc77ce5589: Scheduling FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691): perf score=14.095187
I20260812 06:19:53.817533  9051 maintenance_manager.cc:643] P a72188cff32f43f7ad0b0bdc77ce5589: FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691) complete. Timing: real 0.052s	user 0.030s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20061,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:53.818099  9160 maintenance_manager.cc:419] P a72188cff32f43f7ad0b0bdc77ce5589: Scheduling FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691): perf score=2.188937
I20260812 06:19:53.829030  9051 maintenance_manager.cc:643] P a72188cff32f43f7ad0b0bdc77ce5589: FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4137,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:53.829571  9160 maintenance_manager.cc:419] P a72188cff32f43f7ad0b0bdc77ce5589: Scheduling MajorDeltaCompactionOp(3b090fb666cb4a48a7b20ce1a96b6691): perf score=1.000000
I20260812 06:19:53.978387  9051 maintenance_manager.cc:643] P a72188cff32f43f7ad0b0bdc77ce5589: MajorDeltaCompactionOp(3b090fb666cb4a48a7b20ce1a96b6691) complete. Timing: real 0.149s	user 0.100s	sys 0.039s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":413,"lbm_read_time_us":10383,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27334,"lbm_writes_lt_1ms":543,"mutex_wait_us":19,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12288,"update_count":2500}
I20260812 06:19:53.978974  9160 maintenance_manager.cc:419] P a72188cff32f43f7ad0b0bdc77ce5589: Scheduling FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691): perf score=14.095187
I20260812 06:19:54.020222  9051 maintenance_manager.cc:643] P a72188cff32f43f7ad0b0bdc77ce5589: FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691) complete. Timing: real 0.041s	user 0.024s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17111,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:54.020637  9160 maintenance_manager.cc:419] P a72188cff32f43f7ad0b0bdc77ce5589: Scheduling FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691): perf score=2.188937
I20260812 06:19:54.030232  9051 maintenance_manager.cc:643] P a72188cff32f43f7ad0b0bdc77ce5589: FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691) complete. Timing: real 0.009s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3668,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:54.030669  9160 maintenance_manager.cc:419] P a72188cff32f43f7ad0b0bdc77ce5589: Scheduling MajorDeltaCompactionOp(3b090fb666cb4a48a7b20ce1a96b6691): perf score=1.000000
I20260812 06:19:54.183789  9051 maintenance_manager.cc:643] P a72188cff32f43f7ad0b0bdc77ce5589: MajorDeltaCompactionOp(3b090fb666cb4a48a7b20ce1a96b6691) complete. Timing: real 0.153s	user 0.108s	sys 0.039s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":170,"lbm_read_time_us":11397,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26359,"lbm_writes_lt_1ms":543,"mutex_wait_us":3,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12032,"update_count":2500}
I20260812 06:19:54.184352  9160 maintenance_manager.cc:419] P a72188cff32f43f7ad0b0bdc77ce5589: Scheduling FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691): perf score=12.110812
I20260812 06:19:54.219753  9051 maintenance_manager.cc:643] P a72188cff32f43f7ad0b0bdc77ce5589: FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691) complete. Timing: real 0.035s	user 0.017s	sys 0.016s Metrics: {"bytes_written":13620266,"delete_count":0,"lbm_write_time_us":15488,"lbm_writes_lt_1ms":335,"reinsert_count":0,"update_count":1660}
I20260812 06:19:54.220263  9160 maintenance_manager.cc:419] P a72188cff32f43f7ad0b0bdc77ce5589: Scheduling FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691): perf score=1.196750
I20260812 06:19:54.229030  9051 maintenance_manager.cc:643] P a72188cff32f43f7ad0b0bdc77ce5589: FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691) complete. Timing: real 0.009s	user 0.003s	sys 0.004s Metrics: {"bytes_written":2789855,"delete_count":0,"lbm_write_time_us":3143,"lbm_writes_lt_1ms":71,"reinsert_count":0,"update_count":340}
I20260812 06:19:54.229511  9160 maintenance_manager.cc:419] P a72188cff32f43f7ad0b0bdc77ce5589: Scheduling FlushMRSOp(3b090fb666cb4a48a7b20ce1a96b6691): perf score=1.000000
I20260812 06:19:54.253453  9051 maintenance_manager.cc:643] P a72188cff32f43f7ad0b0bdc77ce5589: FlushMRSOp(3b090fb666cb4a48a7b20ce1a96b6691) complete. Timing: real 0.024s	user 0.022s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":37,"dirs.run_cpu_time_us":159,"dirs.run_wall_time_us":1039,"drs_written":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1543,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:54.254069  9160 maintenance_manager.cc:419] P a72188cff32f43f7ad0b0bdc77ce5589: Scheduling LogGCOp(3b090fb666cb4a48a7b20ce1a96b6691): free 115943172 bytes of WAL
I20260812 06:19:54.254283  9051 log_reader.cc:385] T 3b090fb666cb4a48a7b20ce1a96b6691: removed 11 log segments from log reader
I20260812 06:19:54.254344  9051 log.cc:1079] T 3b090fb666cb4a48a7b20ce1a96b6691 P a72188cff32f43f7ad0b0bdc77ce5589: Deleting log segment in path: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587518819-8548-0/minicluster-data/ts-0-root/wals/3b090fb666cb4a48a7b20ce1a96b6691/wal-000000003 (ops 12-16)
I20260812 06:19:54.254388  9051 log.cc:1079] T 3b090fb666cb4a48a7b20ce1a96b6691 P a72188cff32f43f7ad0b0bdc77ce5589: Deleting log segment in path: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587518819-8548-0/minicluster-data/ts-0-root/wals/3b090fb666cb4a48a7b20ce1a96b6691/wal-000000004 (ops 17-21)
I20260812 06:19:54.254417  9051 log.cc:1079] T 3b090fb666cb4a48a7b20ce1a96b6691 P a72188cff32f43f7ad0b0bdc77ce5589: Deleting log segment in path: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587518819-8548-0/minicluster-data/ts-0-root/wals/3b090fb666cb4a48a7b20ce1a96b6691/wal-000000005 (ops 22-26)
I20260812 06:19:54.254487  9051 log.cc:1079] T 3b090fb666cb4a48a7b20ce1a96b6691 P a72188cff32f43f7ad0b0bdc77ce5589: Deleting log segment in path: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587518819-8548-0/minicluster-data/ts-0-root/wals/3b090fb666cb4a48a7b20ce1a96b6691/wal-000000006 (ops 27-31)
I20260812 06:19:54.254519  9051 log.cc:1079] T 3b090fb666cb4a48a7b20ce1a96b6691 P a72188cff32f43f7ad0b0bdc77ce5589: Deleting log segment in path: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587518819-8548-0/minicluster-data/ts-0-root/wals/3b090fb666cb4a48a7b20ce1a96b6691/wal-000000007 (ops 32-36)
I20260812 06:19:54.254549  9051 log.cc:1079] T 3b090fb666cb4a48a7b20ce1a96b6691 P a72188cff32f43f7ad0b0bdc77ce5589: Deleting log segment in path: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587518819-8548-0/minicluster-data/ts-0-root/wals/3b090fb666cb4a48a7b20ce1a96b6691/wal-000000008 (ops 37-41)
I20260812 06:19:54.254576  9051 log.cc:1079] T 3b090fb666cb4a48a7b20ce1a96b6691 P a72188cff32f43f7ad0b0bdc77ce5589: Deleting log segment in path: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587518819-8548-0/minicluster-data/ts-0-root/wals/3b090fb666cb4a48a7b20ce1a96b6691/wal-000000009 (ops 42-46)
I20260812 06:19:54.254604  9051 log.cc:1079] T 3b090fb666cb4a48a7b20ce1a96b6691 P a72188cff32f43f7ad0b0bdc77ce5589: Deleting log segment in path: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587518819-8548-0/minicluster-data/ts-0-root/wals/3b090fb666cb4a48a7b20ce1a96b6691/wal-000000010 (ops 47-51)
I20260812 06:19:54.254666  9051 log.cc:1079] T 3b090fb666cb4a48a7b20ce1a96b6691 P a72188cff32f43f7ad0b0bdc77ce5589: Deleting log segment in path: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587518819-8548-0/minicluster-data/ts-0-root/wals/3b090fb666cb4a48a7b20ce1a96b6691/wal-000000011 (ops 52-56)
I20260812 06:19:54.254693  9051 log.cc:1079] T 3b090fb666cb4a48a7b20ce1a96b6691 P a72188cff32f43f7ad0b0bdc77ce5589: Deleting log segment in path: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587518819-8548-0/minicluster-data/ts-0-root/wals/3b090fb666cb4a48a7b20ce1a96b6691/wal-000000012 (ops 57-61)
I20260812 06:19:54.254719  9051 log.cc:1079] T 3b090fb666cb4a48a7b20ce1a96b6691 P a72188cff32f43f7ad0b0bdc77ce5589: Deleting log segment in path: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587518819-8548-0/minicluster-data/ts-0-root/wals/3b090fb666cb4a48a7b20ce1a96b6691/wal-000000013 (ops 62-66)
I20260812 06:19:54.279585  9051 maintenance_manager.cc:643] P a72188cff32f43f7ad0b0bdc77ce5589: LogGCOp(3b090fb666cb4a48a7b20ce1a96b6691) complete. Timing: real 0.025s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:19:54.279925  9160 maintenance_manager.cc:419] P a72188cff32f43f7ad0b0bdc77ce5589: Scheduling FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691): perf score=3.181125
I20260812 06:19:54.301996  9051 maintenance_manager.cc:643] P a72188cff32f43f7ad0b0bdc77ce5589: FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691) complete. Timing: real 0.022s	user 0.015s	sys 0.001s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":5948,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:54.302369  9160 maintenance_manager.cc:419] P a72188cff32f43f7ad0b0bdc77ce5589: Scheduling FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691): perf score=2.188937
I20260812 06:19:54.310772  9051 maintenance_manager.cc:643] P a72188cff32f43f7ad0b0bdc77ce5589: FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691) complete. Timing: real 0.008s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3225,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:54.311136  9160 maintenance_manager.cc:419] P a72188cff32f43f7ad0b0bdc77ce5589: Scheduling MajorDeltaCompactionOp(3b090fb666cb4a48a7b20ce1a96b6691): perf score=1.000000
I20260812 06:19:54.496399  9051 maintenance_manager.cc:643] P a72188cff32f43f7ad0b0bdc77ce5589: MajorDeltaCompactionOp(3b090fb666cb4a48a7b20ce1a96b6691) complete. Timing: real 0.185s	user 0.091s	sys 0.091s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918293,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1036,"lbm_read_time_us":12332,"lbm_reads_lt_1ms":674,"lbm_write_time_us":33347,"lbm_writes_lt_1ms":643,"mutex_wait_us":932,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2176,"thread_start_us":73,"threads_started":1,"update_count":3000}
I20260812 06:19:54.496980  9160 maintenance_manager.cc:419] P a72188cff32f43f7ad0b0bdc77ce5589: Scheduling UndoDeltaBlockGCOp(3b090fb666cb4a48a7b20ce1a96b6691): 448 bytes on disk
I20260812 06:19:54.497429  9051 maintenance_manager.cc:643] P a72188cff32f43f7ad0b0bdc77ce5589: UndoDeltaBlockGCOp(3b090fb666cb4a48a7b20ce1a96b6691) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4}
I20260812 06:19:54.497983  9160 maintenance_manager.cc:419] P a72188cff32f43f7ad0b0bdc77ce5589: Scheduling FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691): perf score=14.095187
I20260812 06:19:54.546011  9051 maintenance_manager.cc:643] P a72188cff32f43f7ad0b0bdc77ce5589: FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691) complete. Timing: real 0.048s	user 0.031s	sys 0.017s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":20833,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:54.546542  9160 maintenance_manager.cc:419] P a72188cff32f43f7ad0b0bdc77ce5589: Scheduling FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691): perf score=2.188937
I20260812 06:19:54.567299  9051 maintenance_manager.cc:643] P a72188cff32f43f7ad0b0bdc77ce5589: FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691) complete. Timing: real 0.017s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6245,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:54.567804  9160 maintenance_manager.cc:419] P a72188cff32f43f7ad0b0bdc77ce5589: Scheduling MajorDeltaCompactionOp(3b090fb666cb4a48a7b20ce1a96b6691): perf score=1.000000
I20260812 06:19:54.721803  9051 maintenance_manager.cc:643] P a72188cff32f43f7ad0b0bdc77ce5589: MajorDeltaCompactionOp(3b090fb666cb4a48a7b20ce1a96b6691) complete. Timing: real 0.154s	user 0.115s	sys 0.037s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":141,"lbm_read_time_us":10743,"lbm_reads_lt_1ms":564,"lbm_write_time_us":23305,"lbm_writes_lt_1ms":543,"mutex_wait_us":27,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2500}
I20260812 06:19:54.722359  9160 maintenance_manager.cc:419] P a72188cff32f43f7ad0b0bdc77ce5589: Scheduling FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691): perf score=14.095187
I20260812 06:19:54.771826  9051 maintenance_manager.cc:643] P a72188cff32f43f7ad0b0bdc77ce5589: FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691) complete. Timing: real 0.049s	user 0.039s	sys 0.007s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21854,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:54.772373  9160 maintenance_manager.cc:419] P a72188cff32f43f7ad0b0bdc77ce5589: Scheduling MajorDeltaCompactionOp(3b090fb666cb4a48a7b20ce1a96b6691): perf score=1.000000
I20260812 06:19:54.914714  9051 maintenance_manager.cc:643] P a72188cff32f43f7ad0b0bdc77ce5589: MajorDeltaCompactionOp(3b090fb666cb4a48a7b20ce1a96b6691) complete. Timing: real 0.142s	user 0.081s	sys 0.051s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713153,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":246,"lbm_read_time_us":9385,"lbm_reads_lt_1ms":463,"lbm_write_time_us":21128,"lbm_writes_lt_1ms":443,"mutex_wait_us":43,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9088,"update_count":2000}
I20260812 06:19:54.915251  9160 maintenance_manager.cc:419] P a72188cff32f43f7ad0b0bdc77ce5589: Scheduling FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691): perf score=14.095187
I20260812 06:19:54.968977  9051 maintenance_manager.cc:643] P a72188cff32f43f7ad0b0bdc77ce5589: FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691) complete. Timing: real 0.054s	user 0.022s	sys 0.028s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":23218,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:54.969518  9160 maintenance_manager.cc:419] P a72188cff32f43f7ad0b0bdc77ce5589: Scheduling FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691): perf score=2.188937
I20260812 06:19:54.979665  9051 maintenance_manager.cc:643] P a72188cff32f43f7ad0b0bdc77ce5589: FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3973,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:54.980278  9160 maintenance_manager.cc:419] P a72188cff32f43f7ad0b0bdc77ce5589: Scheduling MajorDeltaCompactionOp(3b090fb666cb4a48a7b20ce1a96b6691): perf score=1.000000
I20260812 06:19:55.155767  9051 maintenance_manager.cc:643] P a72188cff32f43f7ad0b0bdc77ce5589: MajorDeltaCompactionOp(3b090fb666cb4a48a7b20ce1a96b6691) complete. Timing: real 0.175s	user 0.103s	sys 0.063s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815679,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":208,"lbm_read_time_us":9816,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27337,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11904,"update_count":2500}
I20260812 06:19:55.156222  9160 maintenance_manager.cc:419] P a72188cff32f43f7ad0b0bdc77ce5589: Scheduling FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691): perf score=14.095187
I20260812 06:19:55.204345  9051 maintenance_manager.cc:643] P a72188cff32f43f7ad0b0bdc77ce5589: FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691) complete. Timing: real 0.048s	user 0.031s	sys 0.012s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":19788,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:55.204824  9160 maintenance_manager.cc:419] P a72188cff32f43f7ad0b0bdc77ce5589: Scheduling FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691): perf score=2.188937
I20260812 06:19:55.215327  9051 maintenance_manager.cc:643] P a72188cff32f43f7ad0b0bdc77ce5589: FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691) complete. Timing: real 0.010s	user 0.008s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3956,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:55.215921  9160 maintenance_manager.cc:419] P a72188cff32f43f7ad0b0bdc77ce5589: Scheduling MajorDeltaCompactionOp(3b090fb666cb4a48a7b20ce1a96b6691): perf score=1.000000
I20260812 06:19:55.363421  9051 maintenance_manager.cc:643] P a72188cff32f43f7ad0b0bdc77ce5589: MajorDeltaCompactionOp(3b090fb666cb4a48a7b20ce1a96b6691) complete. Timing: real 0.147s	user 0.092s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815680,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1061,"lbm_read_time_us":10849,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26868,"lbm_writes_lt_1ms":543,"mutex_wait_us":267,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12416,"update_count":2500}
I20260812 06:19:55.364249  9160 maintenance_manager.cc:419] P a72188cff32f43f7ad0b0bdc77ce5589: Scheduling FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691): perf score=11.118625
I20260812 06:19:55.401114  9051 maintenance_manager.cc:643] P a72188cff32f43f7ad0b0bdc77ce5589: FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691) complete. Timing: real 0.037s	user 0.002s	sys 0.029s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15291,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:55.401665  9160 maintenance_manager.cc:419] P a72188cff32f43f7ad0b0bdc77ce5589: Scheduling FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691): perf score=2.188937
I20260812 06:19:55.424566  9051 maintenance_manager.cc:643] P a72188cff32f43f7ad0b0bdc77ce5589: FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691) complete. Timing: real 0.023s	user 0.011s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6475,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:55.425099  9160 maintenance_manager.cc:419] P a72188cff32f43f7ad0b0bdc77ce5589: Scheduling FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691): perf score=2.188937
I20260812 06:19:55.437755  9051 maintenance_manager.cc:643] P a72188cff32f43f7ad0b0bdc77ce5589: FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691) complete. Timing: real 0.012s	user 0.003s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4788,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:55.438271  9160 maintenance_manager.cc:419] P a72188cff32f43f7ad0b0bdc77ce5589: Scheduling MajorDeltaCompactionOp(3b090fb666cb4a48a7b20ce1a96b6691): perf score=1.000000
I20260812 06:19:55.592613  9051 maintenance_manager.cc:643] P a72188cff32f43f7ad0b0bdc77ce5589: MajorDeltaCompactionOp(3b090fb666cb4a48a7b20ce1a96b6691) complete. Timing: real 0.154s	user 0.116s	sys 0.037s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815794,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":759,"lbm_read_time_us":12191,"lbm_reads_lt_1ms":573,"lbm_write_time_us":32060,"lbm_writes_lt_1ms":543,"mutex_wait_us":276,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9344,"update_count":2500}
I20260812 06:19:55.593132  9160 maintenance_manager.cc:419] P a72188cff32f43f7ad0b0bdc77ce5589: Scheduling FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691): perf score=11.118625
I20260812 06:19:55.625429  9051 maintenance_manager.cc:643] P a72188cff32f43f7ad0b0bdc77ce5589: FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691) complete. Timing: real 0.032s	user 0.014s	sys 0.015s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":13737,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:55.625944  9160 maintenance_manager.cc:419] P a72188cff32f43f7ad0b0bdc77ce5589: Scheduling FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691): perf score=2.188937
I20260812 06:19:55.650502  9051 maintenance_manager.cc:643] P a72188cff32f43f7ad0b0bdc77ce5589: FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691) complete. Timing: real 0.024s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3938559,"delete_count":0,"lbm_write_time_us":5451,"lbm_writes_lt_1ms":99,"reinsert_count":0,"update_count":480}
I20260812 06:19:55.650987  9160 maintenance_manager.cc:419] P a72188cff32f43f7ad0b0bdc77ce5589: Scheduling FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691): perf score=2.188937
I20260812 06:19:55.660486  9051 maintenance_manager.cc:643] P a72188cff32f43f7ad0b0bdc77ce5589: FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3856509,"delete_count":0,"lbm_write_time_us":3687,"lbm_writes_lt_1ms":97,"reinsert_count":0,"update_count":470}
I20260812 06:19:55.660984  9160 maintenance_manager.cc:419] P a72188cff32f43f7ad0b0bdc77ce5589: Scheduling FlushMRSOp(3b090fb666cb4a48a7b20ce1a96b6691): perf score=1.000000
I20260812 06:19:55.689353  9051 maintenance_manager.cc:643] P a72188cff32f43f7ad0b0bdc77ce5589: FlushMRSOp(3b090fb666cb4a48a7b20ce1a96b6691) complete. Timing: real 0.028s	user 0.020s	sys 0.004s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":49,"dirs.run_cpu_time_us":175,"dirs.run_wall_time_us":1137,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1618,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:55.690062  9160 maintenance_manager.cc:419] P a72188cff32f43f7ad0b0bdc77ce5589: Scheduling LogGCOp(3b090fb666cb4a48a7b20ce1a96b6691): free 121006439 bytes of WAL
I20260812 06:19:55.690284  9051 log_reader.cc:385] T 3b090fb666cb4a48a7b20ce1a96b6691: removed 12 log segments from log reader
I20260812 06:19:55.690344  9051 log.cc:1079] T 3b090fb666cb4a48a7b20ce1a96b6691 P a72188cff32f43f7ad0b0bdc77ce5589: Deleting log segment in path: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587518819-8548-0/minicluster-data/ts-0-root/wals/3b090fb666cb4a48a7b20ce1a96b6691/wal-000000014 (ops 67-71)
I20260812 06:19:55.690389  9051 log.cc:1079] T 3b090fb666cb4a48a7b20ce1a96b6691 P a72188cff32f43f7ad0b0bdc77ce5589: Deleting log segment in path: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587518819-8548-0/minicluster-data/ts-0-root/wals/3b090fb666cb4a48a7b20ce1a96b6691/wal-000000015 (ops 72-76)
I20260812 06:19:55.690416  9051 log.cc:1079] T 3b090fb666cb4a48a7b20ce1a96b6691 P a72188cff32f43f7ad0b0bdc77ce5589: Deleting log segment in path: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587518819-8548-0/minicluster-data/ts-0-root/wals/3b090fb666cb4a48a7b20ce1a96b6691/wal-000000016 (ops 77-81)
I20260812 06:19:55.690443  9051 log.cc:1079] T 3b090fb666cb4a48a7b20ce1a96b6691 P a72188cff32f43f7ad0b0bdc77ce5589: Deleting log segment in path: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587518819-8548-0/minicluster-data/ts-0-root/wals/3b090fb666cb4a48a7b20ce1a96b6691/wal-000000017 (ops 82-86)
I20260812 06:19:55.690472  9051 log.cc:1079] T 3b090fb666cb4a48a7b20ce1a96b6691 P a72188cff32f43f7ad0b0bdc77ce5589: Deleting log segment in path: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587518819-8548-0/minicluster-data/ts-0-root/wals/3b090fb666cb4a48a7b20ce1a96b6691/wal-000000018 (ops 87-91)
I20260812 06:19:55.690505  9051 log.cc:1079] T 3b090fb666cb4a48a7b20ce1a96b6691 P a72188cff32f43f7ad0b0bdc77ce5589: Deleting log segment in path: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587518819-8548-0/minicluster-data/ts-0-root/wals/3b090fb666cb4a48a7b20ce1a96b6691/wal-000000019 (ops 92-96)
I20260812 06:19:55.690536  9051 log.cc:1079] T 3b090fb666cb4a48a7b20ce1a96b6691 P a72188cff32f43f7ad0b0bdc77ce5589: Deleting log segment in path: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587518819-8548-0/minicluster-data/ts-0-root/wals/3b090fb666cb4a48a7b20ce1a96b6691/wal-000000020 (ops 97-100)
I20260812 06:19:55.690562  9051 log.cc:1079] T 3b090fb666cb4a48a7b20ce1a96b6691 P a72188cff32f43f7ad0b0bdc77ce5589: Deleting log segment in path: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587518819-8548-0/minicluster-data/ts-0-root/wals/3b090fb666cb4a48a7b20ce1a96b6691/wal-000000021 (ops 101-105)
I20260812 06:19:55.690590  9051 log.cc:1079] T 3b090fb666cb4a48a7b20ce1a96b6691 P a72188cff32f43f7ad0b0bdc77ce5589: Deleting log segment in path: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587518819-8548-0/minicluster-data/ts-0-root/wals/3b090fb666cb4a48a7b20ce1a96b6691/wal-000000022 (ops 106-110)
I20260812 06:19:55.690615  9051 log.cc:1079] T 3b090fb666cb4a48a7b20ce1a96b6691 P a72188cff32f43f7ad0b0bdc77ce5589: Deleting log segment in path: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587518819-8548-0/minicluster-data/ts-0-root/wals/3b090fb666cb4a48a7b20ce1a96b6691/wal-000000023 (ops 111-115)
I20260812 06:19:55.690647  9051 log.cc:1079] T 3b090fb666cb4a48a7b20ce1a96b6691 P a72188cff32f43f7ad0b0bdc77ce5589: Deleting log segment in path: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587518819-8548-0/minicluster-data/ts-0-root/wals/3b090fb666cb4a48a7b20ce1a96b6691/wal-000000024 (ops 116-120)
I20260812 06:19:55.690677  9051 log.cc:1079] T 3b090fb666cb4a48a7b20ce1a96b6691 P a72188cff32f43f7ad0b0bdc77ce5589: Deleting log segment in path: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587518819-8548-0/minicluster-data/ts-0-root/wals/3b090fb666cb4a48a7b20ce1a96b6691/wal-000000025 (ops 121-125)
I20260812 06:19:55.716832  9051 maintenance_manager.cc:643] P a72188cff32f43f7ad0b0bdc77ce5589: LogGCOp(3b090fb666cb4a48a7b20ce1a96b6691) complete. Timing: real 0.027s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:19:55.717204  9160 maintenance_manager.cc:419] P a72188cff32f43f7ad0b0bdc77ce5589: Scheduling FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691): perf score=3.181125
I20260812 06:19:55.731338  9051 maintenance_manager.cc:643] P a72188cff32f43f7ad0b0bdc77ce5589: FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691) complete. Timing: real 0.014s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4307,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:55.738159  9160 maintenance_manager.cc:419] P a72188cff32f43f7ad0b0bdc77ce5589: Scheduling LogGCOp(3b090fb666cb4a48a7b20ce1a96b6691): free 12017947 bytes of WAL
I20260812 06:19:55.738368  9051 log_reader.cc:385] T 3b090fb666cb4a48a7b20ce1a96b6691: removed 1 log segments from log reader
I20260812 06:19:55.738433  9051 log.cc:1079] T 3b090fb666cb4a48a7b20ce1a96b6691 P a72188cff32f43f7ad0b0bdc77ce5589: Deleting log segment in path: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587518819-8548-0/minicluster-data/ts-0-root/wals/3b090fb666cb4a48a7b20ce1a96b6691/wal-000000026 (ops 126-130)
I20260812 06:19:55.741165  9051 maintenance_manager.cc:643] P a72188cff32f43f7ad0b0bdc77ce5589: LogGCOp(3b090fb666cb4a48a7b20ce1a96b6691) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:19:55.741487  9160 maintenance_manager.cc:419] P a72188cff32f43f7ad0b0bdc77ce5589: Scheduling UndoDeltaBlockGCOp(3b090fb666cb4a48a7b20ce1a96b6691): 472 bytes on disk
I20260812 06:19:55.742107  9051 maintenance_manager.cc:643] P a72188cff32f43f7ad0b0bdc77ce5589: UndoDeltaBlockGCOp(3b090fb666cb4a48a7b20ce1a96b6691) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":92,"lbm_reads_lt_1ms":4}
I20260812 06:19:55.742632  9160 maintenance_manager.cc:419] P a72188cff32f43f7ad0b0bdc77ce5589: Scheduling FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691): perf score=2.188937
I20260812 06:19:55.766454  9051 maintenance_manager.cc:643] P a72188cff32f43f7ad0b0bdc77ce5589: FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691) complete. Timing: real 0.024s	user 0.013s	sys 0.010s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6249,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:55.766948  9160 maintenance_manager.cc:419] P a72188cff32f43f7ad0b0bdc77ce5589: Scheduling MajorDeltaCompactionOp(3b090fb666cb4a48a7b20ce1a96b6691): perf score=1.000000
I20260812 06:19:55.975013  9051 maintenance_manager.cc:643] P a72188cff32f43f7ad0b0bdc77ce5589: MajorDeltaCompactionOp(3b090fb666cb4a48a7b20ce1a96b6691) complete. Timing: real 0.208s	user 0.139s	sys 0.068s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":33020847,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":838,"lbm_read_time_us":15506,"lbm_reads_lt_1ms":767,"lbm_write_time_us":34050,"lbm_writes_lt_1ms":743,"mutex_wait_us":2,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":6016,"thread_start_us":101,"threads_started":1,"update_count":3500}
I20260812 06:19:55.975555  9160 maintenance_manager.cc:419] P a72188cff32f43f7ad0b0bdc77ce5589: Scheduling FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691): perf score=18.063937
I20260812 06:19:56.029754  9051 maintenance_manager.cc:643] P a72188cff32f43f7ad0b0bdc77ce5589: FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691) complete. Timing: real 0.054s	user 0.037s	sys 0.012s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":23365,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:56.030275  9160 maintenance_manager.cc:419] P a72188cff32f43f7ad0b0bdc77ce5589: Scheduling FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691): perf score=2.188937
I20260812 06:19:56.045557  9051 maintenance_manager.cc:643] P a72188cff32f43f7ad0b0bdc77ce5589: FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691) complete. Timing: real 0.015s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6049,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:56.046007  9160 maintenance_manager.cc:419] P a72188cff32f43f7ad0b0bdc77ce5589: Scheduling MajorDeltaCompactionOp(3b090fb666cb4a48a7b20ce1a96b6691): perf score=1.000000
I20260812 06:19:56.230189  9051 maintenance_manager.cc:643] P a72188cff32f43f7ad0b0bdc77ce5589: MajorDeltaCompactionOp(3b090fb666cb4a48a7b20ce1a96b6691) complete. Timing: real 0.184s	user 0.129s	sys 0.054s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918098,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":344,"lbm_read_time_us":12984,"lbm_reads_lt_1ms":672,"lbm_write_time_us":33177,"lbm_writes_lt_1ms":643,"mutex_wait_us":46,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":3000}
I20260812 06:19:56.230665  9160 maintenance_manager.cc:419] P a72188cff32f43f7ad0b0bdc77ce5589: Scheduling FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691): perf score=14.095187
I20260812 06:19:56.278321  9051 maintenance_manager.cc:643] P a72188cff32f43f7ad0b0bdc77ce5589: FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691) complete. Timing: real 0.048s	user 0.035s	sys 0.012s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":21547,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:56.278851  9160 maintenance_manager.cc:419] P a72188cff32f43f7ad0b0bdc77ce5589: Scheduling FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691): perf score=2.188937
I20260812 06:19:56.295095  9051 maintenance_manager.cc:643] P a72188cff32f43f7ad0b0bdc77ce5589: FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691) complete. Timing: real 0.016s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6171,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:56.295552  9160 maintenance_manager.cc:419] P a72188cff32f43f7ad0b0bdc77ce5589: Scheduling MajorDeltaCompactionOp(3b090fb666cb4a48a7b20ce1a96b6691): perf score=1.000000
I20260812 06:19:56.466216  9051 maintenance_manager.cc:643] P a72188cff32f43f7ad0b0bdc77ce5589: MajorDeltaCompactionOp(3b090fb666cb4a48a7b20ce1a96b6691) complete. Timing: real 0.170s	user 0.138s	sys 0.032s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815681,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":238,"lbm_read_time_us":12926,"lbm_reads_lt_1ms":564,"lbm_write_time_us":29142,"lbm_writes_lt_1ms":543,"mutex_wait_us":15,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9472,"update_count":2500}
I20260812 06:19:56.466908  9160 maintenance_manager.cc:419] P a72188cff32f43f7ad0b0bdc77ce5589: Scheduling FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691): perf score=14.095187
I20260812 06:19:56.549368  9051 maintenance_manager.cc:643] P a72188cff32f43f7ad0b0bdc77ce5589: FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691) complete. Timing: real 0.082s	user 0.026s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":50024,"lbm_writes_1-10_ms":1,"lbm_writes_10-100_ms":1,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:19:56.550029  9160 maintenance_manager.cc:419] P a72188cff32f43f7ad0b0bdc77ce5589: Scheduling FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691): perf score=2.188937
I20260812 06:19:56.561348  9051 maintenance_manager.cc:643] P a72188cff32f43f7ad0b0bdc77ce5589: FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691) complete. Timing: real 0.011s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4397,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":500}
I20260812 06:19:56.561863  9160 maintenance_manager.cc:419] P a72188cff32f43f7ad0b0bdc77ce5589: Scheduling MajorDeltaCompactionOp(3b090fb666cb4a48a7b20ce1a96b6691): perf score=1.000000
I20260812 06:19:56.731590  9051 maintenance_manager.cc:643] P a72188cff32f43f7ad0b0bdc77ce5589: MajorDeltaCompactionOp(3b090fb666cb4a48a7b20ce1a96b6691) complete. Timing: real 0.170s	user 0.134s	sys 0.035s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":594,"lbm_read_time_us":12005,"lbm_reads_lt_1ms":568,"lbm_write_time_us":28160,"lbm_writes_lt_1ms":543,"mutex_wait_us":271,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":16768,"update_count":2500}
I20260812 06:19:56.732319  9160 maintenance_manager.cc:419] P a72188cff32f43f7ad0b0bdc77ce5589: Scheduling FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691): perf score=14.095187
I20260812 06:19:56.782232  9051 maintenance_manager.cc:643] P a72188cff32f43f7ad0b0bdc77ce5589: FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691) complete. Timing: real 0.050s	user 0.029s	sys 0.020s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18289,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:56.782706  9160 maintenance_manager.cc:419] P a72188cff32f43f7ad0b0bdc77ce5589: Scheduling FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691): perf score=2.188937
I20260812 06:19:56.792447  9051 maintenance_manager.cc:643] P a72188cff32f43f7ad0b0bdc77ce5589: FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3820,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:56.792824  9160 maintenance_manager.cc:419] P a72188cff32f43f7ad0b0bdc77ce5589: Scheduling MajorDeltaCompactionOp(3b090fb666cb4a48a7b20ce1a96b6691): perf score=1.000000
I20260812 06:19:56.969458  9051 maintenance_manager.cc:643] P a72188cff32f43f7ad0b0bdc77ce5589: MajorDeltaCompactionOp(3b090fb666cb4a48a7b20ce1a96b6691) complete. Timing: real 0.176s	user 0.088s	sys 0.080s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":231,"lbm_read_time_us":11540,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29665,"lbm_writes_lt_1ms":543,"mutex_wait_us":34,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8192,"update_count":2500}
I20260812 06:19:56.970045  9160 maintenance_manager.cc:419] P a72188cff32f43f7ad0b0bdc77ce5589: Scheduling FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691): perf score=14.095187
I20260812 06:19:57.016144  9051 maintenance_manager.cc:643] P a72188cff32f43f7ad0b0bdc77ce5589: FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691) complete. Timing: real 0.046s	user 0.021s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":17607,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:19:57.016714  9160 maintenance_manager.cc:419] P a72188cff32f43f7ad0b0bdc77ce5589: Scheduling FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691): perf score=2.188937
I20260812 06:19:57.027038  9051 maintenance_manager.cc:643] P a72188cff32f43f7ad0b0bdc77ce5589: FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691) complete. Timing: real 0.010s	user 0.008s	sys 0.001s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3830,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:57.027650  9160 maintenance_manager.cc:419] P a72188cff32f43f7ad0b0bdc77ce5589: Scheduling FlushMRSOp(3b090fb666cb4a48a7b20ce1a96b6691): perf score=1.000000
I20260812 06:19:57.067225  9051 maintenance_manager.cc:643] P a72188cff32f43f7ad0b0bdc77ce5589: FlushMRSOp(3b090fb666cb4a48a7b20ce1a96b6691) complete. Timing: real 0.039s	user 0.024s	sys 0.001s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":49,"dirs.run_cpu_time_us":193,"dirs.run_wall_time_us":1098,"drs_written":1,"lbm_read_time_us":36,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1814,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:57.067966  9160 maintenance_manager.cc:419] P a72188cff32f43f7ad0b0bdc77ce5589: Scheduling LogGCOp(3b090fb666cb4a48a7b20ce1a96b6691): free 112239554 bytes of WAL
I20260812 06:19:57.068194  9051 log_reader.cc:385] T 3b090fb666cb4a48a7b20ce1a96b6691: removed 11 log segments from log reader
I20260812 06:19:57.068259  9051 log.cc:1079] T 3b090fb666cb4a48a7b20ce1a96b6691 P a72188cff32f43f7ad0b0bdc77ce5589: Deleting log segment in path: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587518819-8548-0/minicluster-data/ts-0-root/wals/3b090fb666cb4a48a7b20ce1a96b6691/wal-000000027 (ops 131-135)
I20260812 06:19:57.068305  9051 log.cc:1079] T 3b090fb666cb4a48a7b20ce1a96b6691 P a72188cff32f43f7ad0b0bdc77ce5589: Deleting log segment in path: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587518819-8548-0/minicluster-data/ts-0-root/wals/3b090fb666cb4a48a7b20ce1a96b6691/wal-000000028 (ops 136-140)
I20260812 06:19:57.068341  9051 log.cc:1079] T 3b090fb666cb4a48a7b20ce1a96b6691 P a72188cff32f43f7ad0b0bdc77ce5589: Deleting log segment in path: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587518819-8548-0/minicluster-data/ts-0-root/wals/3b090fb666cb4a48a7b20ce1a96b6691/wal-000000029 (ops 141-145)
I20260812 06:19:57.068372  9051 log.cc:1079] T 3b090fb666cb4a48a7b20ce1a96b6691 P a72188cff32f43f7ad0b0bdc77ce5589: Deleting log segment in path: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587518819-8548-0/minicluster-data/ts-0-root/wals/3b090fb666cb4a48a7b20ce1a96b6691/wal-000000030 (ops 146-150)
I20260812 06:19:57.068405  9051 log.cc:1079] T 3b090fb666cb4a48a7b20ce1a96b6691 P a72188cff32f43f7ad0b0bdc77ce5589: Deleting log segment in path: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587518819-8548-0/minicluster-data/ts-0-root/wals/3b090fb666cb4a48a7b20ce1a96b6691/wal-000000031 (ops 151-154)
I20260812 06:19:57.068434  9051 log.cc:1079] T 3b090fb666cb4a48a7b20ce1a96b6691 P a72188cff32f43f7ad0b0bdc77ce5589: Deleting log segment in path: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587518819-8548-0/minicluster-data/ts-0-root/wals/3b090fb666cb4a48a7b20ce1a96b6691/wal-000000032 (ops 155-159)
I20260812 06:19:57.068463  9051 log.cc:1079] T 3b090fb666cb4a48a7b20ce1a96b6691 P a72188cff32f43f7ad0b0bdc77ce5589: Deleting log segment in path: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587518819-8548-0/minicluster-data/ts-0-root/wals/3b090fb666cb4a48a7b20ce1a96b6691/wal-000000033 (ops 160-164)
I20260812 06:19:57.068490  9051 log.cc:1079] T 3b090fb666cb4a48a7b20ce1a96b6691 P a72188cff32f43f7ad0b0bdc77ce5589: Deleting log segment in path: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587518819-8548-0/minicluster-data/ts-0-root/wals/3b090fb666cb4a48a7b20ce1a96b6691/wal-000000034 (ops 165-169)
I20260812 06:19:57.068519  9051 log.cc:1079] T 3b090fb666cb4a48a7b20ce1a96b6691 P a72188cff32f43f7ad0b0bdc77ce5589: Deleting log segment in path: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587518819-8548-0/minicluster-data/ts-0-root/wals/3b090fb666cb4a48a7b20ce1a96b6691/wal-000000035 (ops 170-174)
I20260812 06:19:57.068552  9051 log.cc:1079] T 3b090fb666cb4a48a7b20ce1a96b6691 P a72188cff32f43f7ad0b0bdc77ce5589: Deleting log segment in path: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587518819-8548-0/minicluster-data/ts-0-root/wals/3b090fb666cb4a48a7b20ce1a96b6691/wal-000000036 (ops 175-179)
I20260812 06:19:57.068579  9051 log.cc:1079] T 3b090fb666cb4a48a7b20ce1a96b6691 P a72188cff32f43f7ad0b0bdc77ce5589: Deleting log segment in path: /tmp/dist-test-taskhJHcrn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587518819-8548-0/minicluster-data/ts-0-root/wals/3b090fb666cb4a48a7b20ce1a96b6691/wal-000000037 (ops 180-184)
I20260812 06:19:57.092593  9051 maintenance_manager.cc:643] P a72188cff32f43f7ad0b0bdc77ce5589: LogGCOp(3b090fb666cb4a48a7b20ce1a96b6691) complete. Timing: real 0.024s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:19:57.092996  9160 maintenance_manager.cc:419] P a72188cff32f43f7ad0b0bdc77ce5589: Scheduling FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691): perf score=3.181125
I20260812 06:19:57.113644  9051 maintenance_manager.cc:643] P a72188cff32f43f7ad0b0bdc77ce5589: FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691) complete. Timing: real 0.020s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4388,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:57.114135  9160 maintenance_manager.cc:419] P a72188cff32f43f7ad0b0bdc77ce5589: Scheduling UndoDeltaBlockGCOp(3b090fb666cb4a48a7b20ce1a96b6691): 447 bytes on disk
I20260812 06:19:57.114537  9051 maintenance_manager.cc:643] P a72188cff32f43f7ad0b0bdc77ce5589: UndoDeltaBlockGCOp(3b090fb666cb4a48a7b20ce1a96b6691) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4}
I20260812 06:19:57.115113  9160 maintenance_manager.cc:419] P a72188cff32f43f7ad0b0bdc77ce5589: Scheduling FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691): perf score=2.188937
I20260812 06:19:57.124485  9051 maintenance_manager.cc:643] P a72188cff32f43f7ad0b0bdc77ce5589: FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3638,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:57.124884  9160 maintenance_manager.cc:419] P a72188cff32f43f7ad0b0bdc77ce5589: Scheduling MajorDeltaCompactionOp(3b090fb666cb4a48a7b20ce1a96b6691): perf score=1.000000
I20260812 06:19:57.347400  9051 maintenance_manager.cc:643] P a72188cff32f43f7ad0b0bdc77ce5589: MajorDeltaCompactionOp(3b090fb666cb4a48a7b20ce1a96b6691) complete. Timing: real 0.222s	user 0.127s	sys 0.087s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020732,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":525,"lbm_read_time_us":15162,"lbm_reads_lt_1ms":774,"lbm_write_time_us":36102,"lbm_writes_lt_1ms":743,"mutex_wait_us":248,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":86656,"thread_start_us":74,"threads_started":1,"update_count":3500}
I20260812 06:19:57.347962  9160 maintenance_manager.cc:419] P a72188cff32f43f7ad0b0bdc77ce5589: Scheduling FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691): perf score=18.063937
I20260812 06:19:57.415644  9051 maintenance_manager.cc:643] P a72188cff32f43f7ad0b0bdc77ce5589: FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691) complete. Timing: real 0.067s	user 0.031s	sys 0.020s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":23592,"lbm_writes_lt_1ms":503,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":2500}
I20260812 06:19:57.416124  9160 maintenance_manager.cc:419] P a72188cff32f43f7ad0b0bdc77ce5589: Scheduling FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691): perf score=2.188937
I20260812 06:19:57.430493  9051 maintenance_manager.cc:643] P a72188cff32f43f7ad0b0bdc77ce5589: FlushDeltaMemStoresOp(3b090fb666cb4a48a7b20ce1a96b6691) complete. Timing: real 0.014s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5503,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:57.430969  9160 maintenance_manager.cc:419] P a72188cff32f43f7ad0b0bdc77ce5589: Scheduling MajorDeltaCompactionOp(3b090fb666cb4a48a7b20ce1a96b6691): perf score=1.000000
I20260812 06:19:57.468340  8548 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.672s	user 1.670s	sys 0.171s
I20260812 06:19:57.540215  8548 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.071s	user 0.001s	sys 0.000s
I20260812 06:19:57.540692  8548 tablet_server.cc:179] TabletServer@127.8.89.1:0 shutting down...
I20260812 06:19:57.599234  9051 maintenance_manager.cc:643] P a72188cff32f43f7ad0b0bdc77ce5589: MajorDeltaCompactionOp(3b090fb666cb4a48a7b20ce1a96b6691) complete. Timing: real 0.168s	user 0.106s	sys 0.062s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918099,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":235,"lbm_read_time_us":14565,"lbm_reads_lt_1ms":668,"lbm_write_time_us":27916,"lbm_writes_lt_1ms":643,"mutex_wait_us":46,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":7680,"update_count":3000}
I20260812 06:19:57.599855  8548 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:57.600119  8548 tablet_replica.cc:333] T 3b090fb666cb4a48a7b20ce1a96b6691 P a72188cff32f43f7ad0b0bdc77ce5589: stopping tablet replica
I20260812 06:19:57.600238  8548 raft_consensus.cc:2243] T 3b090fb666cb4a48a7b20ce1a96b6691 P a72188cff32f43f7ad0b0bdc77ce5589 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:57.600414  8548 raft_consensus.cc:2272] T 3b090fb666cb4a48a7b20ce1a96b6691 P a72188cff32f43f7ad0b0bdc77ce5589 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:57.604908  8548 tablet_server.cc:196] TabletServer@127.8.89.1:0 shutdown complete.
I20260812 06:19:57.650369  8548 master.cc:562] Master@127.8.89.62:38873 shutting down...
I20260812 06:19:57.653180  8548 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 42aa5efd7dc54b5e83c5e6cd9bb91ad3 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:57.653335  8548 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 42aa5efd7dc54b5e83c5e6cd9bb91ad3 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:57.653386  8548 tablet_replica.cc:333] T 00000000000000000000000000000000 P 42aa5efd7dc54b5e83c5e6cd9bb91ad3: stopping tablet replica
I20260812 06:19:57.665657  8548 master.cc:584] Master@127.8.89.62:38873 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5126 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10209 ms total)

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