[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:18:10.389963 24798 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.24.55.190:40337
I20260812 06:18:10.390957 24798 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:18:10.391566 24798 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:10.397779 24808 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:10.397842 24798 server_base.cc:1061] running on GCE node
W20260812 06:18:10.397794 24811 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:10.398082 24809 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:10.398576 24798 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:10.398697 24798 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:10.398761 24798 hybrid_clock.cc:648] HybridClock initialized: now 1786515490398759 us; error 0 us; skew 500 ppm
I20260812 06:18:10.400447 24798 webserver.cc:533] Webserver started at http://127.24.55.190:34609/ using document root <none> and password file <none>
I20260812 06:18:10.400974 24798 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:10.401059 24798 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:10.401309 24798 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:10.402884 24798 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515490379373-24798-0/minicluster-data/master-0-root/instance:
uuid: "c10f876259fa4337b4a7e0855108b89f"
format_stamp: "Formatted at 2026-08-12 06:18:10 on dist-test-slave-gmjp"
I20260812 06:18:10.406229 24798 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.005s	sys 0.000s
I20260812 06:18:10.408269 24818 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:10.409173 24798 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:10.409304 24798 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515490379373-24798-0/minicluster-data/master-0-root
uuid: "c10f876259fa4337b4a7e0855108b89f"
format_stamp: "Formatted at 2026-08-12 06:18:10 on dist-test-slave-gmjp"
I20260812 06:18:10.409403 24798 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515490379373-24798-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515490379373-24798-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515490379373-24798-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:10.422776 24798 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:10.423352 24798 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:18:10.423530 24798 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:10.431332 24798 rpc_server.cc:307] RPC server started. Bound to: 127.24.55.190:40337
I20260812 06:18:10.431344 24904 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.24.55.190:40337 every 8 connection(s)
I20260812 06:18:10.433553 24905 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:10.438836 24905 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P c10f876259fa4337b4a7e0855108b89f: Bootstrap starting.
I20260812 06:18:10.441272 24905 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P c10f876259fa4337b4a7e0855108b89f: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:10.442173 24905 log.cc:826] T 00000000000000000000000000000000 P c10f876259fa4337b4a7e0855108b89f: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:10.443831 24905 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P c10f876259fa4337b4a7e0855108b89f: No bootstrap required, opened a new log
I20260812 06:18:10.446530 24905 raft_consensus.cc:359] T 00000000000000000000000000000000 P c10f876259fa4337b4a7e0855108b89f [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c10f876259fa4337b4a7e0855108b89f" member_type: VOTER }
I20260812 06:18:10.446689 24905 raft_consensus.cc:385] T 00000000000000000000000000000000 P c10f876259fa4337b4a7e0855108b89f [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:10.446830 24905 raft_consensus.cc:740] T 00000000000000000000000000000000 P c10f876259fa4337b4a7e0855108b89f [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: c10f876259fa4337b4a7e0855108b89f, State: Initialized, Role: FOLLOWER
I20260812 06:18:10.447419 24905 consensus_queue.cc:260] T 00000000000000000000000000000000 P c10f876259fa4337b4a7e0855108b89f [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: "c10f876259fa4337b4a7e0855108b89f" member_type: VOTER }
I20260812 06:18:10.447587 24905 raft_consensus.cc:399] T 00000000000000000000000000000000 P c10f876259fa4337b4a7e0855108b89f [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:10.447656 24905 raft_consensus.cc:493] T 00000000000000000000000000000000 P c10f876259fa4337b4a7e0855108b89f [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:10.447819 24905 raft_consensus.cc:3060] T 00000000000000000000000000000000 P c10f876259fa4337b4a7e0855108b89f [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:10.448686 24905 raft_consensus.cc:515] T 00000000000000000000000000000000 P c10f876259fa4337b4a7e0855108b89f [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c10f876259fa4337b4a7e0855108b89f" member_type: VOTER }
I20260812 06:18:10.449128 24905 leader_election.cc:304] T 00000000000000000000000000000000 P c10f876259fa4337b4a7e0855108b89f [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: c10f876259fa4337b4a7e0855108b89f; no voters: 
I20260812 06:18:10.449455 24905 leader_election.cc:290] T 00000000000000000000000000000000 P c10f876259fa4337b4a7e0855108b89f [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:10.449592 24911 raft_consensus.cc:2804] T 00000000000000000000000000000000 P c10f876259fa4337b4a7e0855108b89f [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:10.449841 24911 raft_consensus.cc:697] T 00000000000000000000000000000000 P c10f876259fa4337b4a7e0855108b89f [term 1 LEADER]: Becoming Leader. State: Replica: c10f876259fa4337b4a7e0855108b89f, State: Running, Role: LEADER
I20260812 06:18:10.450233 24911 consensus_queue.cc:237] T 00000000000000000000000000000000 P c10f876259fa4337b4a7e0855108b89f [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: "c10f876259fa4337b4a7e0855108b89f" member_type: VOTER }
I20260812 06:18:10.450510 24905 sys_catalog.cc:565] T 00000000000000000000000000000000 P c10f876259fa4337b4a7e0855108b89f [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:10.452023 24914 sys_catalog.cc:455] T 00000000000000000000000000000000 P c10f876259fa4337b4a7e0855108b89f [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "c10f876259fa4337b4a7e0855108b89f" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c10f876259fa4337b4a7e0855108b89f" member_type: VOTER } }
I20260812 06:18:10.452154 24914 sys_catalog.cc:458] T 00000000000000000000000000000000 P c10f876259fa4337b4a7e0855108b89f [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:10.452593 24915 sys_catalog.cc:455] T 00000000000000000000000000000000 P c10f876259fa4337b4a7e0855108b89f [sys.catalog]: SysCatalogTable state changed. Reason: New leader c10f876259fa4337b4a7e0855108b89f. Latest consensus state: current_term: 1 leader_uuid: "c10f876259fa4337b4a7e0855108b89f" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c10f876259fa4337b4a7e0855108b89f" member_type: VOTER } }
I20260812 06:18:10.452695 24915 sys_catalog.cc:458] T 00000000000000000000000000000000 P c10f876259fa4337b4a7e0855108b89f [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:10.452821 24798 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:18:10.454838 24948 catalog_manager.cc:1594] T 00000000000000000000000000000000 P c10f876259fa4337b4a7e0855108b89f: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:18:10.454927 24948 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:18:10.455014 24942 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:10.455767 24942 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:10.460412 24942 catalog_manager.cc:1383] Generated new cluster ID: 2edc545e5e2641649e53b742f8b7176f
I20260812 06:18:10.460475 24942 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:10.475351 24942 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:10.476325 24942 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:10.491371 24942 catalog_manager.cc:6092] T 00000000000000000000000000000000 P c10f876259fa4337b4a7e0855108b89f: Generated new TSK 0
I20260812 06:18:10.492187 24942 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:10.517709 24798 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:10.520714 24952 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:10.520800 24958 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:10.520722 24953 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:10.521224 24798 server_base.cc:1061] running on GCE node
I20260812 06:18:10.521396 24798 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:10.521453 24798 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:10.521488 24798 hybrid_clock.cc:648] HybridClock initialized: now 1786515490521487 us; error 0 us; skew 500 ppm
I20260812 06:18:10.522440 24798 webserver.cc:533] Webserver started at http://127.24.55.129:46417/ using document root <none> and password file <none>
I20260812 06:18:10.522629 24798 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:10.522704 24798 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:10.522786 24798 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:10.523205 24798 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515490379373-24798-0/minicluster-data/ts-0-root/instance:
uuid: "02c154d34cba4de48fb60c75f4059c24"
format_stamp: "Formatted at 2026-08-12 06:18:10 on dist-test-slave-gmjp"
I20260812 06:18:10.524829 24798 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:18:10.525818 24964 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:10.526072 24798 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:10.526135 24798 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515490379373-24798-0/minicluster-data/ts-0-root
uuid: "02c154d34cba4de48fb60c75f4059c24"
format_stamp: "Formatted at 2026-08-12 06:18:10 on dist-test-slave-gmjp"
I20260812 06:18:10.526222 24798 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515490379373-24798-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515490379373-24798-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515490379373-24798-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:10.545584 24798 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:10.546054 24798 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:10.546586 24798 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:10.547499 24798 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:10.547554 24798 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:10.547624 24798 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:10.547670 24798 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:10.554718 24798 rpc_server.cc:307] RPC server started. Bound to: 127.24.55.129:35671
I20260812 06:18:10.554807 25067 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.24.55.129:35671 every 8 connection(s)
I20260812 06:18:10.565006 25068 heartbeater.cc:344] Connected to a master server at 127.24.55.190:40337
I20260812 06:18:10.565259 25068 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:10.565755 25068 heartbeater.cc:507] Master 127.24.55.190:40337 requested a full tablet report, sending...
I20260812 06:18:10.567176 24847 ts_manager.cc:194] Registered new tserver with Master: 02c154d34cba4de48fb60c75f4059c24 (127.24.55.129:35671)
I20260812 06:18:10.567755 24798 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012359369s
I20260812 06:18:10.568658 24847 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:34254
I20260812 06:18:10.577414 24847 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:34258:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:10.591535 25007 tablet_service.cc:1511] Processing CreateTablet for tablet 464e7a256db648d18b1d9b96f151bc0f (DEFAULT_TABLE table=heavy-update-compaction-test [id=8315c9aae104413285d0f76203598926]), partition=
I20260812 06:18:10.592024 25007 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 464e7a256db648d18b1d9b96f151bc0f. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:10.594342 25099 tablet_bootstrap.cc:492] T 464e7a256db648d18b1d9b96f151bc0f P 02c154d34cba4de48fb60c75f4059c24: Bootstrap starting.
I20260812 06:18:10.595355 25099 tablet_bootstrap.cc:654] T 464e7a256db648d18b1d9b96f151bc0f P 02c154d34cba4de48fb60c75f4059c24: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:10.596956 25099 tablet_bootstrap.cc:492] T 464e7a256db648d18b1d9b96f151bc0f P 02c154d34cba4de48fb60c75f4059c24: No bootstrap required, opened a new log
I20260812 06:18:10.597048 25099 ts_tablet_manager.cc:1403] T 464e7a256db648d18b1d9b96f151bc0f P 02c154d34cba4de48fb60c75f4059c24: Time spent bootstrapping tablet: real 0.003s	user 0.000s	sys 0.002s
I20260812 06:18:10.597499 25099 raft_consensus.cc:359] T 464e7a256db648d18b1d9b96f151bc0f P 02c154d34cba4de48fb60c75f4059c24 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "02c154d34cba4de48fb60c75f4059c24" member_type: VOTER last_known_addr { host: "127.24.55.129" port: 35671 } }
I20260812 06:18:10.597596 25099 raft_consensus.cc:385] T 464e7a256db648d18b1d9b96f151bc0f P 02c154d34cba4de48fb60c75f4059c24 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:10.597620 25099 raft_consensus.cc:740] T 464e7a256db648d18b1d9b96f151bc0f P 02c154d34cba4de48fb60c75f4059c24 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 02c154d34cba4de48fb60c75f4059c24, State: Initialized, Role: FOLLOWER
I20260812 06:18:10.597766 25099 consensus_queue.cc:260] T 464e7a256db648d18b1d9b96f151bc0f P 02c154d34cba4de48fb60c75f4059c24 [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: "02c154d34cba4de48fb60c75f4059c24" member_type: VOTER last_known_addr { host: "127.24.55.129" port: 35671 } }
I20260812 06:18:10.597852 25099 raft_consensus.cc:399] T 464e7a256db648d18b1d9b96f151bc0f P 02c154d34cba4de48fb60c75f4059c24 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:10.597879 25099 raft_consensus.cc:493] T 464e7a256db648d18b1d9b96f151bc0f P 02c154d34cba4de48fb60c75f4059c24 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:10.597957 25099 raft_consensus.cc:3060] T 464e7a256db648d18b1d9b96f151bc0f P 02c154d34cba4de48fb60c75f4059c24 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:10.598692 25099 raft_consensus.cc:515] T 464e7a256db648d18b1d9b96f151bc0f P 02c154d34cba4de48fb60c75f4059c24 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "02c154d34cba4de48fb60c75f4059c24" member_type: VOTER last_known_addr { host: "127.24.55.129" port: 35671 } }
I20260812 06:18:10.598810 25099 leader_election.cc:304] T 464e7a256db648d18b1d9b96f151bc0f P 02c154d34cba4de48fb60c75f4059c24 [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: 02c154d34cba4de48fb60c75f4059c24; no voters: 
I20260812 06:18:10.599094 25099 leader_election.cc:290] T 464e7a256db648d18b1d9b96f151bc0f P 02c154d34cba4de48fb60c75f4059c24 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:10.599184 25102 raft_consensus.cc:2804] T 464e7a256db648d18b1d9b96f151bc0f P 02c154d34cba4de48fb60c75f4059c24 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:10.599457 25099 ts_tablet_manager.cc:1434] T 464e7a256db648d18b1d9b96f151bc0f P 02c154d34cba4de48fb60c75f4059c24: Time spent starting tablet: real 0.002s	user 0.000s	sys 0.003s
I20260812 06:18:10.599439 25102 raft_consensus.cc:697] T 464e7a256db648d18b1d9b96f151bc0f P 02c154d34cba4de48fb60c75f4059c24 [term 1 LEADER]: Becoming Leader. State: Replica: 02c154d34cba4de48fb60c75f4059c24, State: Running, Role: LEADER
I20260812 06:18:10.599864 25068 heartbeater.cc:499] Master 127.24.55.190:40337 was elected leader, sending a full tablet report...
I20260812 06:18:10.599913 25102 consensus_queue.cc:237] T 464e7a256db648d18b1d9b96f151bc0f P 02c154d34cba4de48fb60c75f4059c24 [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: "02c154d34cba4de48fb60c75f4059c24" member_type: VOTER last_known_addr { host: "127.24.55.129" port: 35671 } }
I20260812 06:18:10.602856 24847 catalog_manager.cc:5719] T 464e7a256db648d18b1d9b96f151bc0f P 02c154d34cba4de48fb60c75f4059c24 reported cstate change: term changed from 0 to 1, leader changed from <none> to 02c154d34cba4de48fb60c75f4059c24 (127.24.55.129). New cstate: current_term: 1 leader_uuid: "02c154d34cba4de48fb60c75f4059c24" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "02c154d34cba4de48fb60c75f4059c24" member_type: VOTER last_known_addr { host: "127.24.55.129" port: 35671 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:10.663264 24798 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.055s	user 0.021s	sys 0.005s
I20260812 06:18:10.805826 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling FlushMRSOp(464e7a256db648d18b1d9b96f151bc0f): perf score=19.054940
I20260812 06:18:10.979656 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: FlushMRSOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.173s	user 0.142s	sys 0.028s Metrics: {"bytes_written":12307491,"cfile_init":1,"compiler_manager_pool.queue_time_us":314,"delete_count":0,"dirs.queue_time_us":79,"dirs.run_cpu_time_us":199,"dirs.run_wall_time_us":724,"drs_written":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4,"lbm_write_time_us":43703,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":179,"threads_started":1,"update_count":1500}
I20260812 06:18:10.980931 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling LogGCOp(464e7a256db648d18b1d9b96f151bc0f): free 20743880 bytes of WAL
I20260812 06:18:10.981251 24970 log_reader.cc:385] T 464e7a256db648d18b1d9b96f151bc0f: removed 2 log segments from log reader
I20260812 06:18:10.981314 24970 log.cc:1079] T 464e7a256db648d18b1d9b96f151bc0f P 02c154d34cba4de48fb60c75f4059c24: Deleting log segment in path: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515490379373-24798-0/minicluster-data/ts-0-root/wals/464e7a256db648d18b1d9b96f151bc0f/wal-000000001 (ops 1-6)
I20260812 06:18:10.981369 24970 log.cc:1079] T 464e7a256db648d18b1d9b96f151bc0f P 02c154d34cba4de48fb60c75f4059c24: Deleting log segment in path: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515490379373-24798-0/minicluster-data/ts-0-root/wals/464e7a256db648d18b1d9b96f151bc0f/wal-000000002 (ops 7-11)
I20260812 06:18:10.986918 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: LogGCOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.006s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:18:10.987252 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f): perf score=2.188937
I20260812 06:18:11.005093 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.018s	user 0.015s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7258,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:11.005564 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling UndoDeltaBlockGCOp(464e7a256db648d18b1d9b96f151bc0f): 16411394 bytes on disk
I20260812 06:18:11.006094 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: UndoDeltaBlockGCOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":46,"lbm_reads_lt_1ms":4}
I20260812 06:18:11.006492 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling MajorDeltaCompactionOp(464e7a256db648d18b1d9b96f151bc0f): perf score=1.000000
I20260812 06:18:11.143551 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: MajorDeltaCompactionOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.137s	user 0.094s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":595,"lbm_read_time_us":7381,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23598,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":335,"threads_started":5,"update_count":2000}
I20260812 06:18:11.144264 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f): perf score=10.126437
I20260812 06:18:11.190594 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.046s	user 0.034s	sys 0.004s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":17578,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:11.191282 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f): perf score=2.188937
I20260812 06:18:11.206265 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.015s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5652,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:11.206907 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling MajorDeltaCompactionOp(464e7a256db648d18b1d9b96f151bc0f): perf score=1.000000
I20260812 06:18:11.336874 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: MajorDeltaCompactionOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.130s	user 0.094s	sys 0.031s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":210,"lbm_read_time_us":9048,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25822,"lbm_writes_lt_1ms":443,"mutex_wait_us":45,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7808,"update_count":2000}
I20260812 06:18:11.337494 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f): perf score=10.126437
I20260812 06:18:11.369861 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.032s	user 0.021s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12918,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:11.370350 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling MajorDeltaCompactionOp(464e7a256db648d18b1d9b96f151bc0f): perf score=1.000000
I20260812 06:18:11.469969 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: MajorDeltaCompactionOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.099s	user 0.077s	sys 0.022s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569746,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1099,"lbm_read_time_us":5788,"lbm_reads_lt_1ms":363,"lbm_write_time_us":21480,"lbm_writes_lt_1ms":343,"mutex_wait_us":332,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":1500}
I20260812 06:18:11.470542 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f): perf score=10.126437
I20260812 06:18:11.515247 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.045s	user 0.032s	sys 0.001s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":15426,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:11.515714 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f): perf score=2.188937
I20260812 06:18:11.526276 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.010s	user 0.005s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3797,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:11.526873 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling MajorDeltaCompactionOp(464e7a256db648d18b1d9b96f151bc0f): perf score=1.000000
I20260812 06:18:11.676110 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: MajorDeltaCompactionOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.149s	user 0.113s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":554,"lbm_read_time_us":9490,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27199,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7424,"update_count":2000}
I20260812 06:18:11.676584 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f): perf score=10.126437
I20260812 06:18:11.720377 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.044s	user 0.018s	sys 0.024s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20201,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:18:11.720808 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f): perf score=2.188937
I20260812 06:18:11.731158 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4019,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:11.731674 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling MajorDeltaCompactionOp(464e7a256db648d18b1d9b96f151bc0f): perf score=1.000000
I20260812 06:18:11.863147 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: MajorDeltaCompactionOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.131s	user 0.095s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":132,"lbm_read_time_us":8402,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25620,"lbm_writes_lt_1ms":443,"mutex_wait_us":25,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:11.863693 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f): perf score=10.126437
I20260812 06:18:11.898602 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.034s	user 0.024s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17072,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:18:11.901458 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f): perf score=2.188937
I20260812 06:18:11.917502 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.016s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5779,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:11.917923 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling MajorDeltaCompactionOp(464e7a256db648d18b1d9b96f151bc0f): perf score=1.000000
I20260812 06:18:12.038120 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: MajorDeltaCompactionOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.120s	user 0.100s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":61,"lbm_read_time_us":7033,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23664,"lbm_writes_lt_1ms":443,"mutex_wait_us":2,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:18:12.038830 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f): perf score=11.118625
I20260812 06:18:12.084630 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.045s	user 0.028s	sys 0.016s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16238,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:12.085253 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f): perf score=2.188937
I20260812 06:18:12.095978 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4127,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:12.096613 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling MajorDeltaCompactionOp(464e7a256db648d18b1d9b96f151bc0f): perf score=1.000000
I20260812 06:18:12.240592 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: MajorDeltaCompactionOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.144s	user 0.111s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1064,"lbm_read_time_us":10550,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23768,"lbm_writes_lt_1ms":443,"mutex_wait_us":316,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:12.241173 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f): perf score=10.126437
I20260812 06:18:12.279350 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.038s	user 0.016s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15112,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:12.279812 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f): perf score=2.188937
I20260812 06:18:12.290802 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.011s	user 0.005s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3923,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:12.291517 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling FlushMRSOp(464e7a256db648d18b1d9b96f151bc0f): perf score=1.000000
I20260812 06:18:12.325086 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: FlushMRSOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.033s	user 0.028s	sys 0.004s Metrics: {"bytes_written":1275443,"cfile_init":1,"dirs.queue_time_us":73,"dirs.run_cpu_time_us":261,"dirs.run_wall_time_us":1246,"drs_written":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1677,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:12.325845 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling LogGCOp(464e7a256db648d18b1d9b96f151bc0f): free 120553374 bytes of WAL
I20260812 06:18:12.326066 24970 log_reader.cc:385] T 464e7a256db648d18b1d9b96f151bc0f: removed 12 log segments from log reader
I20260812 06:18:12.326128 24970 log.cc:1079] T 464e7a256db648d18b1d9b96f151bc0f P 02c154d34cba4de48fb60c75f4059c24: Deleting log segment in path: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515490379373-24798-0/minicluster-data/ts-0-root/wals/464e7a256db648d18b1d9b96f151bc0f/wal-000000003 (ops 12-16)
I20260812 06:18:12.326181 24970 log.cc:1079] T 464e7a256db648d18b1d9b96f151bc0f P 02c154d34cba4de48fb60c75f4059c24: Deleting log segment in path: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515490379373-24798-0/minicluster-data/ts-0-root/wals/464e7a256db648d18b1d9b96f151bc0f/wal-000000004 (ops 17-21)
I20260812 06:18:12.326239 24970 log.cc:1079] T 464e7a256db648d18b1d9b96f151bc0f P 02c154d34cba4de48fb60c75f4059c24: Deleting log segment in path: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515490379373-24798-0/minicluster-data/ts-0-root/wals/464e7a256db648d18b1d9b96f151bc0f/wal-000000005 (ops 22-26)
I20260812 06:18:12.326282 24970 log.cc:1079] T 464e7a256db648d18b1d9b96f151bc0f P 02c154d34cba4de48fb60c75f4059c24: Deleting log segment in path: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515490379373-24798-0/minicluster-data/ts-0-root/wals/464e7a256db648d18b1d9b96f151bc0f/wal-000000006 (ops 27-31)
I20260812 06:18:12.326316 24970 log.cc:1079] T 464e7a256db648d18b1d9b96f151bc0f P 02c154d34cba4de48fb60c75f4059c24: Deleting log segment in path: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515490379373-24798-0/minicluster-data/ts-0-root/wals/464e7a256db648d18b1d9b96f151bc0f/wal-000000007 (ops 32-36)
I20260812 06:18:12.326364 24970 log.cc:1079] T 464e7a256db648d18b1d9b96f151bc0f P 02c154d34cba4de48fb60c75f4059c24: Deleting log segment in path: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515490379373-24798-0/minicluster-data/ts-0-root/wals/464e7a256db648d18b1d9b96f151bc0f/wal-000000008 (ops 37-40)
I20260812 06:18:12.326401 24970 log.cc:1079] T 464e7a256db648d18b1d9b96f151bc0f P 02c154d34cba4de48fb60c75f4059c24: Deleting log segment in path: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515490379373-24798-0/minicluster-data/ts-0-root/wals/464e7a256db648d18b1d9b96f151bc0f/wal-000000009 (ops 41-45)
I20260812 06:18:12.326437 24970 log.cc:1079] T 464e7a256db648d18b1d9b96f151bc0f P 02c154d34cba4de48fb60c75f4059c24: Deleting log segment in path: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515490379373-24798-0/minicluster-data/ts-0-root/wals/464e7a256db648d18b1d9b96f151bc0f/wal-000000010 (ops 46-50)
I20260812 06:18:12.326473 24970 log.cc:1079] T 464e7a256db648d18b1d9b96f151bc0f P 02c154d34cba4de48fb60c75f4059c24: Deleting log segment in path: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515490379373-24798-0/minicluster-data/ts-0-root/wals/464e7a256db648d18b1d9b96f151bc0f/wal-000000011 (ops 51-55)
I20260812 06:18:12.326510 24970 log.cc:1079] T 464e7a256db648d18b1d9b96f151bc0f P 02c154d34cba4de48fb60c75f4059c24: Deleting log segment in path: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515490379373-24798-0/minicluster-data/ts-0-root/wals/464e7a256db648d18b1d9b96f151bc0f/wal-000000012 (ops 56-60)
I20260812 06:18:12.326546 24970 log.cc:1079] T 464e7a256db648d18b1d9b96f151bc0f P 02c154d34cba4de48fb60c75f4059c24: Deleting log segment in path: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515490379373-24798-0/minicluster-data/ts-0-root/wals/464e7a256db648d18b1d9b96f151bc0f/wal-000000013 (ops 61-64)
I20260812 06:18:12.326583 24970 log.cc:1079] T 464e7a256db648d18b1d9b96f151bc0f P 02c154d34cba4de48fb60c75f4059c24: Deleting log segment in path: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515490379373-24798-0/minicluster-data/ts-0-root/wals/464e7a256db648d18b1d9b96f151bc0f/wal-000000014 (ops 65-69)
I20260812 06:18:12.350869 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: LogGCOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.025s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:18:12.351399 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling UndoDeltaBlockGCOp(464e7a256db648d18b1d9b96f151bc0f): 482 bytes on disk
I20260812 06:18:12.352130 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: UndoDeltaBlockGCOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":72,"lbm_reads_lt_1ms":4}
I20260812 06:18:12.352782 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f): perf score=4.173312
I20260812 06:18:12.377583 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.025s	user 0.009s	sys 0.014s Metrics: {"bytes_written":6276941,"delete_count":0,"lbm_write_time_us":7292,"lbm_writes_lt_1ms":156,"mutex_wait_us":137,"reinsert_count":0,"update_count":765}
I20260812 06:18:12.378074 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling LogGCOp(464e7a256db648d18b1d9b96f151bc0f): free 12017932 bytes of WAL
I20260812 06:18:12.378296 24970 log_reader.cc:385] T 464e7a256db648d18b1d9b96f151bc0f: removed 1 log segments from log reader
I20260812 06:18:12.378341 24970 log.cc:1079] T 464e7a256db648d18b1d9b96f151bc0f P 02c154d34cba4de48fb60c75f4059c24: Deleting log segment in path: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515490379373-24798-0/minicluster-data/ts-0-root/wals/464e7a256db648d18b1d9b96f151bc0f/wal-000000015 (ops 70-74)
I20260812 06:18:12.380712 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: LogGCOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.002s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:18:12.381024 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f): perf score=1.000000
I20260812 06:18:12.386739 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.006s	user 0.003s	sys 0.001s Metrics: {"bytes_written":1928327,"delete_count":0,"lbm_write_time_us":1791,"lbm_writes_lt_1ms":50,"reinsert_count":0,"update_count":235}
I20260812 06:18:12.387248 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling MajorDeltaCompactionOp(464e7a256db648d18b1d9b96f151bc0f): perf score=1.000000
I20260812 06:18:12.598996 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: MajorDeltaCompactionOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.212s	user 0.151s	sys 0.050s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877283,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":3482,"lbm_read_time_us":14332,"lbm_reads_lt_1ms":674,"lbm_write_time_us":34756,"lbm_writes_lt_1ms":643,"mutex_wait_us":1574,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3456,"thread_start_us":72,"threads_started":1,"update_count":3000}
I20260812 06:18:12.599545 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f): perf score=14.095187
I20260812 06:18:12.661526 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.062s	user 0.033s	sys 0.027s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":22390,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:12.662079 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f): perf score=2.188937
I20260812 06:18:12.672605 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4076,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:12.673032 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling MajorDeltaCompactionOp(464e7a256db648d18b1d9b96f151bc0f): perf score=1.000000
I20260812 06:18:12.849104 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: MajorDeltaCompactionOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.176s	user 0.112s	sys 0.064s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":354,"lbm_read_time_us":12702,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30579,"lbm_writes_lt_1ms":543,"mutex_wait_us":108,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:18:12.849669 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f): perf score=10.126437
I20260812 06:18:12.889961 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.040s	user 0.011s	sys 0.027s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16235,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:12.890589 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f): perf score=2.188937
I20260812 06:18:12.912989 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.022s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5645,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:12.913451 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f): perf score=2.188937
I20260812 06:18:12.927758 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.014s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5611,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:12.928303 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling MajorDeltaCompactionOp(464e7a256db648d18b1d9b96f151bc0f): perf score=1.000000
I20260812 06:18:13.108381 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: MajorDeltaCompactionOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.180s	user 0.110s	sys 0.063s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774809,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":329,"lbm_read_time_us":10655,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30901,"lbm_writes_lt_1ms":543,"mutex_wait_us":56,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9856,"update_count":2500}
I20260812 06:18:13.109004 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f): perf score=11.118625
I20260812 06:18:13.155318 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.046s	user 0.032s	sys 0.009s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":18994,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:13.155862 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f): perf score=2.188937
I20260812 06:18:13.177103 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.021s	user 0.007s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4830,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:13.177611 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f): perf score=2.188937
I20260812 06:18:13.194689 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.017s	user 0.009s	sys 0.006s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6286,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:13.195250 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling MajorDeltaCompactionOp(464e7a256db648d18b1d9b96f151bc0f): perf score=1.000000
I20260812 06:18:13.357376 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: MajorDeltaCompactionOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.162s	user 0.119s	sys 0.040s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":629,"lbm_read_time_us":11440,"lbm_reads_lt_1ms":573,"lbm_write_time_us":32928,"lbm_writes_lt_1ms":543,"mutex_wait_us":34,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":119808,"update_count":2500}
I20260812 06:18:13.358001 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f): perf score=11.118625
I20260812 06:18:13.393836 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.036s	user 0.022s	sys 0.012s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15669,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:13.394673 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f): perf score=2.188937
I20260812 06:18:13.408720 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.014s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4123,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:13.409319 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling MajorDeltaCompactionOp(464e7a256db648d18b1d9b96f151bc0f): perf score=1.000000
I20260812 06:18:13.537441 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: MajorDeltaCompactionOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.128s	user 0.102s	sys 0.026s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":395,"lbm_read_time_us":7299,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26567,"lbm_writes_lt_1ms":443,"mutex_wait_us":41,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10112,"update_count":2000}
I20260812 06:18:13.538125 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f): perf score=10.126437
I20260812 06:18:13.578060 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.040s	user 0.017s	sys 0.021s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":17787,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:13.578588 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f): perf score=2.188937
I20260812 06:18:13.589581 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.011s	user 0.004s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3958,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:13.590065 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling MajorDeltaCompactionOp(464e7a256db648d18b1d9b96f151bc0f): perf score=1.000000
I20260812 06:18:13.721539 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: MajorDeltaCompactionOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.131s	user 0.096s	sys 0.035s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":180,"lbm_read_time_us":9881,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25048,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":16384,"update_count":2000}
I20260812 06:18:13.722101 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f): perf score=10.126437
I20260812 06:18:13.775573 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.053s	user 0.030s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20477,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:18:13.776067 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f): perf score=2.188937
I20260812 06:18:13.786376 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3990,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:13.786844 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling FlushMRSOp(464e7a256db648d18b1d9b96f151bc0f): perf score=1.000000
I20260812 06:18:13.827528 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: FlushMRSOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.040s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":71,"dirs.run_cpu_time_us":213,"dirs.run_wall_time_us":1229,"drs_written":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1501,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:13.828299 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling LogGCOp(464e7a256db648d18b1d9b96f151bc0f): free 112692378 bytes of WAL
I20260812 06:18:13.828521 24970 log_reader.cc:385] T 464e7a256db648d18b1d9b96f151bc0f: removed 11 log segments from log reader
I20260812 06:18:13.828567 24970 log.cc:1079] T 464e7a256db648d18b1d9b96f151bc0f P 02c154d34cba4de48fb60c75f4059c24: Deleting log segment in path: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515490379373-24798-0/minicluster-data/ts-0-root/wals/464e7a256db648d18b1d9b96f151bc0f/wal-000000016 (ops 75-79)
I20260812 06:18:13.828619 24970 log.cc:1079] T 464e7a256db648d18b1d9b96f151bc0f P 02c154d34cba4de48fb60c75f4059c24: Deleting log segment in path: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515490379373-24798-0/minicluster-data/ts-0-root/wals/464e7a256db648d18b1d9b96f151bc0f/wal-000000017 (ops 80-84)
I20260812 06:18:13.828666 24970 log.cc:1079] T 464e7a256db648d18b1d9b96f151bc0f P 02c154d34cba4de48fb60c75f4059c24: Deleting log segment in path: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515490379373-24798-0/minicluster-data/ts-0-root/wals/464e7a256db648d18b1d9b96f151bc0f/wal-000000018 (ops 85-89)
I20260812 06:18:13.828711 24970 log.cc:1079] T 464e7a256db648d18b1d9b96f151bc0f P 02c154d34cba4de48fb60c75f4059c24: Deleting log segment in path: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515490379373-24798-0/minicluster-data/ts-0-root/wals/464e7a256db648d18b1d9b96f151bc0f/wal-000000019 (ops 90-94)
I20260812 06:18:13.828753 24970 log.cc:1079] T 464e7a256db648d18b1d9b96f151bc0f P 02c154d34cba4de48fb60c75f4059c24: Deleting log segment in path: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515490379373-24798-0/minicluster-data/ts-0-root/wals/464e7a256db648d18b1d9b96f151bc0f/wal-000000020 (ops 95-99)
I20260812 06:18:13.828794 24970 log.cc:1079] T 464e7a256db648d18b1d9b96f151bc0f P 02c154d34cba4de48fb60c75f4059c24: Deleting log segment in path: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515490379373-24798-0/minicluster-data/ts-0-root/wals/464e7a256db648d18b1d9b96f151bc0f/wal-000000021 (ops 100-104)
I20260812 06:18:13.828833 24970 log.cc:1079] T 464e7a256db648d18b1d9b96f151bc0f P 02c154d34cba4de48fb60c75f4059c24: Deleting log segment in path: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515490379373-24798-0/minicluster-data/ts-0-root/wals/464e7a256db648d18b1d9b96f151bc0f/wal-000000022 (ops 105-109)
I20260812 06:18:13.828877 24970 log.cc:1079] T 464e7a256db648d18b1d9b96f151bc0f P 02c154d34cba4de48fb60c75f4059c24: Deleting log segment in path: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515490379373-24798-0/minicluster-data/ts-0-root/wals/464e7a256db648d18b1d9b96f151bc0f/wal-000000023 (ops 110-114)
I20260812 06:18:13.828917 24970 log.cc:1079] T 464e7a256db648d18b1d9b96f151bc0f P 02c154d34cba4de48fb60c75f4059c24: Deleting log segment in path: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515490379373-24798-0/minicluster-data/ts-0-root/wals/464e7a256db648d18b1d9b96f151bc0f/wal-000000024 (ops 115-119)
I20260812 06:18:13.828964 24970 log.cc:1079] T 464e7a256db648d18b1d9b96f151bc0f P 02c154d34cba4de48fb60c75f4059c24: Deleting log segment in path: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515490379373-24798-0/minicluster-data/ts-0-root/wals/464e7a256db648d18b1d9b96f151bc0f/wal-000000025 (ops 120-124)
I20260812 06:18:13.829005 24970 log.cc:1079] T 464e7a256db648d18b1d9b96f151bc0f P 02c154d34cba4de48fb60c75f4059c24: Deleting log segment in path: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515490379373-24798-0/minicluster-data/ts-0-root/wals/464e7a256db648d18b1d9b96f151bc0f/wal-000000026 (ops 125-129)
I20260812 06:18:13.853662 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: LogGCOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.025s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:18:13.854031 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling UndoDeltaBlockGCOp(464e7a256db648d18b1d9b96f151bc0f): 463 bytes on disk
I20260812 06:18:13.854451 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: UndoDeltaBlockGCOp(464e7a256db648d18b1d9b96f151bc0f) 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:18:13.854959 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f): perf score=2.188937
I20260812 06:18:13.876778 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.022s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5864,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:13.877226 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f): perf score=2.188937
I20260812 06:18:13.887214 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3886,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:13.887638 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling MajorDeltaCompactionOp(464e7a256db648d18b1d9b96f151bc0f): perf score=1.000000
I20260812 06:18:14.091342 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: MajorDeltaCompactionOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.204s	user 0.135s	sys 0.068s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877339,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":511,"lbm_read_time_us":12958,"lbm_reads_lt_1ms":674,"lbm_write_time_us":36840,"lbm_writes_lt_1ms":643,"mutex_wait_us":22,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":20736,"thread_start_us":82,"threads_started":1,"update_count":3000}
I20260812 06:18:14.092126 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f): perf score=14.095187
I20260812 06:18:14.156241 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.064s	user 0.038s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24803,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:14.156693 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f): perf score=2.188937
I20260812 06:18:14.167306 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4085,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:14.167779 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling MajorDeltaCompactionOp(464e7a256db648d18b1d9b96f151bc0f): perf score=1.000000
I20260812 06:18:14.337637 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: MajorDeltaCompactionOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.170s	user 0.124s	sys 0.043s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":690,"lbm_read_time_us":12053,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31324,"lbm_writes_lt_1ms":543,"mutex_wait_us":308,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8320,"update_count":2500}
I20260812 06:18:14.338286 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f): perf score=14.095187
I20260812 06:18:14.396811 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.058s	user 0.043s	sys 0.008s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22938,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:14.397344 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f): perf score=2.188937
I20260812 06:18:14.410646 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4757,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:14.411121 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling MajorDeltaCompactionOp(464e7a256db648d18b1d9b96f151bc0f): perf score=1.000000
I20260812 06:18:14.590715 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: MajorDeltaCompactionOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.179s	user 0.125s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":295,"lbm_read_time_us":12885,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31326,"lbm_writes_lt_1ms":543,"mutex_wait_us":49,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2500}
I20260812 06:18:14.591432 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f): perf score=14.095187
I20260812 06:18:14.647518 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.056s	user 0.028s	sys 0.022s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20324,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:14.648114 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f): perf score=2.188937
I20260812 06:18:14.659013 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4316,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:14.659462 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling MajorDeltaCompactionOp(464e7a256db648d18b1d9b96f151bc0f): perf score=1.000000
I20260812 06:18:14.836619 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: MajorDeltaCompactionOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.177s	user 0.117s	sys 0.059s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":154,"lbm_read_time_us":13409,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31253,"lbm_writes_lt_1ms":543,"mutex_wait_us":29,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:18:14.837366 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f): perf score=11.118625
I20260812 06:18:14.867823 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.030s	user 0.016s	sys 0.012s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":13508,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:14.868435 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f): perf score=2.188937
I20260812 06:18:14.883837 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5714,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:14.884531 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling MajorDeltaCompactionOp(464e7a256db648d18b1d9b96f151bc0f): perf score=1.000000
I20260812 06:18:15.042536 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: MajorDeltaCompactionOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.158s	user 0.113s	sys 0.037s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672269,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":324,"lbm_read_time_us":9210,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24225,"lbm_writes_lt_1ms":443,"mutex_wait_us":73,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:18:15.043289 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f): perf score=11.118625
I20260812 06:18:15.081959 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.038s	user 0.021s	sys 0.015s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":16265,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:15.082612 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f): perf score=2.188937
I20260812 06:18:15.099139 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.016s	user 0.004s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5427,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:15.099597 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling MajorDeltaCompactionOp(464e7a256db648d18b1d9b96f151bc0f): perf score=1.000000
I20260812 06:18:15.233296 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: MajorDeltaCompactionOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.134s	user 0.098s	sys 0.035s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672267,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":512,"lbm_read_time_us":7268,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26510,"lbm_writes_lt_1ms":443,"mutex_wait_us":262,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":17024,"update_count":2000}
I20260812 06:18:15.234050 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f): perf score=10.126437
I20260812 06:18:15.270457 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.036s	user 0.026s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15256,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:15.271198 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f): perf score=2.188937
I20260812 06:18:15.283185 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4441,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:15.283674 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling FlushMRSOp(464e7a256db648d18b1d9b96f151bc0f): perf score=1.000000
I20260812 06:18:15.314685 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: FlushMRSOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.031s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1193507,"cfile_init":1,"dirs.queue_time_us":70,"dirs.run_cpu_time_us":237,"dirs.run_wall_time_us":1224,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1884,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:15.315367 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling LogGCOp(464e7a256db648d18b1d9b96f151bc0f): free 121006697 bytes of WAL
I20260812 06:18:15.315618 24970 log_reader.cc:385] T 464e7a256db648d18b1d9b96f151bc0f: removed 12 log segments from log reader
I20260812 06:18:15.315665 24970 log.cc:1079] T 464e7a256db648d18b1d9b96f151bc0f P 02c154d34cba4de48fb60c75f4059c24: Deleting log segment in path: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515490379373-24798-0/minicluster-data/ts-0-root/wals/464e7a256db648d18b1d9b96f151bc0f/wal-000000027 (ops 130-134)
I20260812 06:18:15.315692 24970 log.cc:1079] T 464e7a256db648d18b1d9b96f151bc0f P 02c154d34cba4de48fb60c75f4059c24: Deleting log segment in path: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515490379373-24798-0/minicluster-data/ts-0-root/wals/464e7a256db648d18b1d9b96f151bc0f/wal-000000028 (ops 135-139)
I20260812 06:18:15.315757 24970 log.cc:1079] T 464e7a256db648d18b1d9b96f151bc0f P 02c154d34cba4de48fb60c75f4059c24: Deleting log segment in path: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515490379373-24798-0/minicluster-data/ts-0-root/wals/464e7a256db648d18b1d9b96f151bc0f/wal-000000029 (ops 140-144)
I20260812 06:18:15.315795 24970 log.cc:1079] T 464e7a256db648d18b1d9b96f151bc0f P 02c154d34cba4de48fb60c75f4059c24: Deleting log segment in path: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515490379373-24798-0/minicluster-data/ts-0-root/wals/464e7a256db648d18b1d9b96f151bc0f/wal-000000030 (ops 145-149)
I20260812 06:18:15.315838 24970 log.cc:1079] T 464e7a256db648d18b1d9b96f151bc0f P 02c154d34cba4de48fb60c75f4059c24: Deleting log segment in path: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515490379373-24798-0/minicluster-data/ts-0-root/wals/464e7a256db648d18b1d9b96f151bc0f/wal-000000031 (ops 150-154)
I20260812 06:18:15.315891 24970 log.cc:1079] T 464e7a256db648d18b1d9b96f151bc0f P 02c154d34cba4de48fb60c75f4059c24: Deleting log segment in path: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515490379373-24798-0/minicluster-data/ts-0-root/wals/464e7a256db648d18b1d9b96f151bc0f/wal-000000032 (ops 155-158)
I20260812 06:18:15.315929 24970 log.cc:1079] T 464e7a256db648d18b1d9b96f151bc0f P 02c154d34cba4de48fb60c75f4059c24: Deleting log segment in path: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515490379373-24798-0/minicluster-data/ts-0-root/wals/464e7a256db648d18b1d9b96f151bc0f/wal-000000033 (ops 159-163)
I20260812 06:18:15.315980 24970 log.cc:1079] T 464e7a256db648d18b1d9b96f151bc0f P 02c154d34cba4de48fb60c75f4059c24: Deleting log segment in path: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515490379373-24798-0/minicluster-data/ts-0-root/wals/464e7a256db648d18b1d9b96f151bc0f/wal-000000034 (ops 164-168)
I20260812 06:18:15.316021 24970 log.cc:1079] T 464e7a256db648d18b1d9b96f151bc0f P 02c154d34cba4de48fb60c75f4059c24: Deleting log segment in path: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515490379373-24798-0/minicluster-data/ts-0-root/wals/464e7a256db648d18b1d9b96f151bc0f/wal-000000035 (ops 169-173)
I20260812 06:18:15.316061 24970 log.cc:1079] T 464e7a256db648d18b1d9b96f151bc0f P 02c154d34cba4de48fb60c75f4059c24: Deleting log segment in path: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515490379373-24798-0/minicluster-data/ts-0-root/wals/464e7a256db648d18b1d9b96f151bc0f/wal-000000036 (ops 174-178)
I20260812 06:18:15.316100 24970 log.cc:1079] T 464e7a256db648d18b1d9b96f151bc0f P 02c154d34cba4de48fb60c75f4059c24: Deleting log segment in path: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515490379373-24798-0/minicluster-data/ts-0-root/wals/464e7a256db648d18b1d9b96f151bc0f/wal-000000037 (ops 179-183)
I20260812 06:18:15.316139 24970 log.cc:1079] T 464e7a256db648d18b1d9b96f151bc0f P 02c154d34cba4de48fb60c75f4059c24: Deleting log segment in path: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515490379373-24798-0/minicluster-data/ts-0-root/wals/464e7a256db648d18b1d9b96f151bc0f/wal-000000038 (ops 184-188)
I20260812 06:18:15.343148 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: LogGCOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.028s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:18:15.343539 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f): perf score=3.181125
I20260812 06:18:15.365021 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.021s	user 0.009s	sys 0.008s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":7047,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:15.365459 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling UndoDeltaBlockGCOp(464e7a256db648d18b1d9b96f151bc0f): 462 bytes on disk
I20260812 06:18:15.365844 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: UndoDeltaBlockGCOp(464e7a256db648d18b1d9b96f151bc0f) 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:18:15.366384 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f): perf score=2.188937
I20260812 06:18:15.376231 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3611,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:15.376744 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling MajorDeltaCompactionOp(464e7a256db648d18b1d9b96f151bc0f): perf score=1.000000
I20260812 06:18:15.538187 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: MajorDeltaCompactionOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.161s	user 0.120s	sys 0.039s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877329,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":3518,"lbm_read_time_us":12385,"lbm_reads_lt_1ms":674,"lbm_write_time_us":31378,"lbm_writes_lt_1ms":643,"mutex_wait_us":1507,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":15872,"thread_start_us":91,"threads_started":1,"update_count":3000}
I20260812 06:18:15.538910 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f): perf score=14.095187
I20260812 06:18:15.585502 24798 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.922s	user 1.780s	sys 0.132s
I20260812 06:18:15.594427 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.055s	user 0.031s	sys 0.023s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":29233,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":400,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:18:15.594951 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f): perf score=2.188937
I20260812 06:18:15.604521 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: FlushDeltaMemStoresOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.009s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3868,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:15.604959 25072 maintenance_manager.cc:419] P 02c154d34cba4de48fb60c75f4059c24: Scheduling MajorDeltaCompactionOp(464e7a256db648d18b1d9b96f151bc0f): perf score=1.000000
I20260812 06:18:15.616439 24798 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.030s	user 0.004s	sys 0.000s
I20260812 06:18:15.617086 24798 tablet_server.cc:179] TabletServer@127.24.55.129:0 shutting down...
I20260812 06:18:15.722316 24970 maintenance_manager.cc:643] P 02c154d34cba4de48fb60c75f4059c24: MajorDeltaCompactionOp(464e7a256db648d18b1d9b96f151bc0f) complete. Timing: real 0.117s	user 0.089s	sys 0.028s Metrics: {"cfile_cache_hit":30,"cfile_cache_hit_bytes":4262390,"cfile_cache_miss":502,"cfile_cache_miss_bytes":20512296,"cfile_init":4,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":869,"lbm_read_time_us":8137,"lbm_reads_lt_1ms":518,"lbm_write_time_us":23599,"lbm_writes_lt_1ms":543,"mutex_wait_us":304,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":31360,"update_count":2500}
I20260812 06:18:15.723196 24798 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:15.723596 24798 tablet_replica.cc:333] T 464e7a256db648d18b1d9b96f151bc0f P 02c154d34cba4de48fb60c75f4059c24: stopping tablet replica
I20260812 06:18:15.723832 24798 raft_consensus.cc:2243] T 464e7a256db648d18b1d9b96f151bc0f P 02c154d34cba4de48fb60c75f4059c24 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:15.724072 24798 raft_consensus.cc:2272] T 464e7a256db648d18b1d9b96f151bc0f P 02c154d34cba4de48fb60c75f4059c24 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:15.739627 24798 tablet_server.cc:196] TabletServer@127.24.55.129:0 shutdown complete.
I20260812 06:18:15.768304 24798 master.cc:562] Master@127.24.55.190:40337 shutting down...
I20260812 06:18:15.772089 24798 raft_consensus.cc:2243] T 00000000000000000000000000000000 P c10f876259fa4337b4a7e0855108b89f [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:15.772295 24798 raft_consensus.cc:2272] T 00000000000000000000000000000000 P c10f876259fa4337b4a7e0855108b89f [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:15.772404 24798 tablet_replica.cc:333] T 00000000000000000000000000000000 P c10f876259fa4337b4a7e0855108b89f: stopping tablet replica
I20260812 06:18:15.784703 24798 master.cc:584] Master@127.24.55.190:40337 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5485 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:15.887101 24798 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.24.55.190:44453
I20260812 06:18:15.887555 24798 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:15.889674 25136 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:15.889771 25139 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:15.889859 24798 server_base.cc:1061] running on GCE node
W20260812 06:18:15.889771 25133 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:15.890148 24798 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:15.890193 24798 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:15.890209 24798 hybrid_clock.cc:648] HybridClock initialized: now 1786515495890209 us; error 0 us; skew 500 ppm
I20260812 06:18:15.891037 24798 webserver.cc:533] Webserver started at http://127.24.55.190:45497/ using document root <none> and password file <none>
I20260812 06:18:15.891170 24798 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:15.891212 24798 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:15.891266 24798 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:15.891610 24798 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515490379373-24798-0/minicluster-data/master-0-root/instance:
uuid: "bdae10314c944030ad2a1c0a070ff03f"
format_stamp: "Formatted at 2026-08-12 06:18:15 on dist-test-slave-gmjp"
I20260812 06:18:15.893149 24798 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:18:15.894042 25146 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:15.894279 24798 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:15.894342 24798 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515490379373-24798-0/minicluster-data/master-0-root
uuid: "bdae10314c944030ad2a1c0a070ff03f"
format_stamp: "Formatted at 2026-08-12 06:18:15 on dist-test-slave-gmjp"
I20260812 06:18:15.894393 24798 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515490379373-24798-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515490379373-24798-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515490379373-24798-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:15.915692 24798 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:15.916060 24798 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:15.920097 24798 rpc_server.cc:307] RPC server started. Bound to: 127.24.55.190:44453
I20260812 06:18:15.922662 25241 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.24.55.190:44453 every 8 connection(s)
I20260812 06:18:15.923106 25242 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:15.924928 25242 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P bdae10314c944030ad2a1c0a070ff03f: Bootstrap starting.
I20260812 06:18:15.925644 25242 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P bdae10314c944030ad2a1c0a070ff03f: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:15.926573 25242 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P bdae10314c944030ad2a1c0a070ff03f: No bootstrap required, opened a new log
I20260812 06:18:15.926935 25242 raft_consensus.cc:359] T 00000000000000000000000000000000 P bdae10314c944030ad2a1c0a070ff03f [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bdae10314c944030ad2a1c0a070ff03f" member_type: VOTER }
I20260812 06:18:15.927026 25242 raft_consensus.cc:385] T 00000000000000000000000000000000 P bdae10314c944030ad2a1c0a070ff03f [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:15.927047 25242 raft_consensus.cc:740] T 00000000000000000000000000000000 P bdae10314c944030ad2a1c0a070ff03f [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: bdae10314c944030ad2a1c0a070ff03f, State: Initialized, Role: FOLLOWER
I20260812 06:18:15.927147 25242 consensus_queue.cc:260] T 00000000000000000000000000000000 P bdae10314c944030ad2a1c0a070ff03f [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: "bdae10314c944030ad2a1c0a070ff03f" member_type: VOTER }
I20260812 06:18:15.927204 25242 raft_consensus.cc:399] T 00000000000000000000000000000000 P bdae10314c944030ad2a1c0a070ff03f [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:15.927227 25242 raft_consensus.cc:493] T 00000000000000000000000000000000 P bdae10314c944030ad2a1c0a070ff03f [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:15.927256 25242 raft_consensus.cc:3060] T 00000000000000000000000000000000 P bdae10314c944030ad2a1c0a070ff03f [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:15.927851 25242 raft_consensus.cc:515] T 00000000000000000000000000000000 P bdae10314c944030ad2a1c0a070ff03f [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bdae10314c944030ad2a1c0a070ff03f" member_type: VOTER }
I20260812 06:18:15.927966 25242 leader_election.cc:304] T 00000000000000000000000000000000 P bdae10314c944030ad2a1c0a070ff03f [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: bdae10314c944030ad2a1c0a070ff03f; no voters: 
I20260812 06:18:15.928108 25242 leader_election.cc:290] T 00000000000000000000000000000000 P bdae10314c944030ad2a1c0a070ff03f [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:15.928261 25248 raft_consensus.cc:2804] T 00000000000000000000000000000000 P bdae10314c944030ad2a1c0a070ff03f [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:15.928507 25248 raft_consensus.cc:697] T 00000000000000000000000000000000 P bdae10314c944030ad2a1c0a070ff03f [term 1 LEADER]: Becoming Leader. State: Replica: bdae10314c944030ad2a1c0a070ff03f, State: Running, Role: LEADER
I20260812 06:18:15.928599 25242 sys_catalog.cc:565] T 00000000000000000000000000000000 P bdae10314c944030ad2a1c0a070ff03f [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:15.928639 25248 consensus_queue.cc:237] T 00000000000000000000000000000000 P bdae10314c944030ad2a1c0a070ff03f [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: "bdae10314c944030ad2a1c0a070ff03f" member_type: VOTER }
I20260812 06:18:15.929122 25250 sys_catalog.cc:455] T 00000000000000000000000000000000 P bdae10314c944030ad2a1c0a070ff03f [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "bdae10314c944030ad2a1c0a070ff03f" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bdae10314c944030ad2a1c0a070ff03f" member_type: VOTER } }
I20260812 06:18:15.929177 25252 sys_catalog.cc:455] T 00000000000000000000000000000000 P bdae10314c944030ad2a1c0a070ff03f [sys.catalog]: SysCatalogTable state changed. Reason: New leader bdae10314c944030ad2a1c0a070ff03f. Latest consensus state: current_term: 1 leader_uuid: "bdae10314c944030ad2a1c0a070ff03f" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bdae10314c944030ad2a1c0a070ff03f" member_type: VOTER } }
I20260812 06:18:15.929302 25252 sys_catalog.cc:458] T 00000000000000000000000000000000 P bdae10314c944030ad2a1c0a070ff03f [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:15.929575 25250 sys_catalog.cc:458] T 00000000000000000000000000000000 P bdae10314c944030ad2a1c0a070ff03f [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:15.929831 25261 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:15.930672 25261 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:15.930856 24798 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:15.932564 25261 catalog_manager.cc:1383] Generated new cluster ID: 08c6a235b4d34d57b328ff8004c29a8d
I20260812 06:18:15.932623 25261 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:15.948426 25261 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:15.948969 25261 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:15.955178 25261 catalog_manager.cc:6092] T 00000000000000000000000000000000 P bdae10314c944030ad2a1c0a070ff03f: Generated new TSK 0
I20260812 06:18:15.955340 25261 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:15.963240 24798 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:15.965144 25281 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:15.965265 25285 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:15.965301 25283 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:15.965483 24798 server_base.cc:1061] running on GCE node
I20260812 06:18:15.965662 24798 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:15.965700 24798 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:15.965715 24798 hybrid_clock.cc:648] HybridClock initialized: now 1786515495965716 us; error 0 us; skew 500 ppm
I20260812 06:18:15.966596 24798 webserver.cc:533] Webserver started at http://127.24.55.129:33741/ using document root <none> and password file <none>
I20260812 06:18:15.966774 24798 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:15.966873 24798 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:15.966969 24798 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:15.967367 24798 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515490379373-24798-0/minicluster-data/ts-0-root/instance:
uuid: "bf6f9d63bcc6497195faf94d2405d297"
format_stamp: "Formatted at 2026-08-12 06:18:15 on dist-test-slave-gmjp"
I20260812 06:18:15.968925 24798 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:18:15.969841 25298 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:15.970077 24798 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:15.970167 24798 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515490379373-24798-0/minicluster-data/ts-0-root
uuid: "bf6f9d63bcc6497195faf94d2405d297"
format_stamp: "Formatted at 2026-08-12 06:18:15 on dist-test-slave-gmjp"
I20260812 06:18:15.970252 24798 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515490379373-24798-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515490379373-24798-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515490379373-24798-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:15.999053 24798 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:15.999469 24798 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:15.999814 24798 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:16.000329 24798 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:16.000394 24798 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:16.000455 24798 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:16.000510 24798 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:16.004899 24798 rpc_server.cc:307] RPC server started. Bound to: 127.24.55.129:45235
I20260812 06:18:16.006361 25411 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.24.55.129:45235 every 8 connection(s)
I20260812 06:18:16.014264 25413 heartbeater.cc:344] Connected to a master server at 127.24.55.190:44453
I20260812 06:18:16.014390 25413 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:16.014619 25413 heartbeater.cc:507] Master 127.24.55.190:44453 requested a full tablet report, sending...
I20260812 06:18:16.015295 25173 ts_manager.cc:194] Registered new tserver with Master: bf6f9d63bcc6497195faf94d2405d297 (127.24.55.129:45235)
I20260812 06:18:16.015676 24798 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.009900653s
I20260812 06:18:16.016268 25173 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:41246
I20260812 06:18:16.022326 25173 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:41252:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:16.030656 25343 tablet_service.cc:1511] Processing CreateTablet for tablet b06bbf78eaa44dd097880909de0bfbad (DEFAULT_TABLE table=heavy-update-compaction-test [id=3f084b88cafe4d2ea4f6c8c019cf3f9d]), partition=
I20260812 06:18:16.030910 25343 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet b06bbf78eaa44dd097880909de0bfbad. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:16.033087 25438 tablet_bootstrap.cc:492] T b06bbf78eaa44dd097880909de0bfbad P bf6f9d63bcc6497195faf94d2405d297: Bootstrap starting.
I20260812 06:18:16.033929 25438 tablet_bootstrap.cc:654] T b06bbf78eaa44dd097880909de0bfbad P bf6f9d63bcc6497195faf94d2405d297: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:16.034994 25438 tablet_bootstrap.cc:492] T b06bbf78eaa44dd097880909de0bfbad P bf6f9d63bcc6497195faf94d2405d297: No bootstrap required, opened a new log
I20260812 06:18:16.035104 25438 ts_tablet_manager.cc:1403] T b06bbf78eaa44dd097880909de0bfbad P bf6f9d63bcc6497195faf94d2405d297: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:18:16.035539 25438 raft_consensus.cc:359] T b06bbf78eaa44dd097880909de0bfbad P bf6f9d63bcc6497195faf94d2405d297 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bf6f9d63bcc6497195faf94d2405d297" member_type: VOTER last_known_addr { host: "127.24.55.129" port: 45235 } }
I20260812 06:18:16.035663 25438 raft_consensus.cc:385] T b06bbf78eaa44dd097880909de0bfbad P bf6f9d63bcc6497195faf94d2405d297 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:16.035709 25438 raft_consensus.cc:740] T b06bbf78eaa44dd097880909de0bfbad P bf6f9d63bcc6497195faf94d2405d297 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: bf6f9d63bcc6497195faf94d2405d297, State: Initialized, Role: FOLLOWER
I20260812 06:18:16.035859 25438 consensus_queue.cc:260] T b06bbf78eaa44dd097880909de0bfbad P bf6f9d63bcc6497195faf94d2405d297 [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: "bf6f9d63bcc6497195faf94d2405d297" member_type: VOTER last_known_addr { host: "127.24.55.129" port: 45235 } }
I20260812 06:18:16.035970 25438 raft_consensus.cc:399] T b06bbf78eaa44dd097880909de0bfbad P bf6f9d63bcc6497195faf94d2405d297 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:16.036033 25438 raft_consensus.cc:493] T b06bbf78eaa44dd097880909de0bfbad P bf6f9d63bcc6497195faf94d2405d297 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:16.036093 25438 raft_consensus.cc:3060] T b06bbf78eaa44dd097880909de0bfbad P bf6f9d63bcc6497195faf94d2405d297 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:16.036826 25438 raft_consensus.cc:515] T b06bbf78eaa44dd097880909de0bfbad P bf6f9d63bcc6497195faf94d2405d297 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bf6f9d63bcc6497195faf94d2405d297" member_type: VOTER last_known_addr { host: "127.24.55.129" port: 45235 } }
I20260812 06:18:16.037003 25438 leader_election.cc:304] T b06bbf78eaa44dd097880909de0bfbad P bf6f9d63bcc6497195faf94d2405d297 [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: bf6f9d63bcc6497195faf94d2405d297; no voters: 
I20260812 06:18:16.037212 25438 leader_election.cc:290] T b06bbf78eaa44dd097880909de0bfbad P bf6f9d63bcc6497195faf94d2405d297 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:16.037336 25440 raft_consensus.cc:2804] T b06bbf78eaa44dd097880909de0bfbad P bf6f9d63bcc6497195faf94d2405d297 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:16.037542 25438 ts_tablet_manager.cc:1434] T b06bbf78eaa44dd097880909de0bfbad P bf6f9d63bcc6497195faf94d2405d297: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:18:16.037571 25440 raft_consensus.cc:697] T b06bbf78eaa44dd097880909de0bfbad P bf6f9d63bcc6497195faf94d2405d297 [term 1 LEADER]: Becoming Leader. State: Replica: bf6f9d63bcc6497195faf94d2405d297, State: Running, Role: LEADER
I20260812 06:18:16.037580 25413 heartbeater.cc:499] Master 127.24.55.190:44453 was elected leader, sending a full tablet report...
I20260812 06:18:16.037773 25440 consensus_queue.cc:237] T b06bbf78eaa44dd097880909de0bfbad P bf6f9d63bcc6497195faf94d2405d297 [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: "bf6f9d63bcc6497195faf94d2405d297" member_type: VOTER last_known_addr { host: "127.24.55.129" port: 45235 } }
I20260812 06:18:16.039108 25173 catalog_manager.cc:5719] T b06bbf78eaa44dd097880909de0bfbad P bf6f9d63bcc6497195faf94d2405d297 reported cstate change: term changed from 0 to 1, leader changed from <none> to bf6f9d63bcc6497195faf94d2405d297 (127.24.55.129). New cstate: current_term: 1 leader_uuid: "bf6f9d63bcc6497195faf94d2405d297" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bf6f9d63bcc6497195faf94d2405d297" member_type: VOTER last_known_addr { host: "127.24.55.129" port: 45235 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:16.099071 24798 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.053s	user 0.015s	sys 0.008s
I20260812 06:18:16.256951 25416 maintenance_manager.cc:419] P bf6f9d63bcc6497195faf94d2405d297: Scheduling FlushMRSOp(b06bbf78eaa44dd097880909de0bfbad): perf score=19.054940
I20260812 06:18:16.415728 25305 maintenance_manager.cc:643] P bf6f9d63bcc6497195faf94d2405d297: FlushMRSOp(b06bbf78eaa44dd097880909de0bfbad) complete. Timing: real 0.158s	user 0.126s	sys 0.028s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":85,"dirs.run_cpu_time_us":255,"dirs.run_wall_time_us":873,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":41445,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:18:16.416694 25416 maintenance_manager.cc:419] P bf6f9d63bcc6497195faf94d2405d297: Scheduling LogGCOp(b06bbf78eaa44dd097880909de0bfbad): free 20743880 bytes of WAL
I20260812 06:18:16.416985 25305 log_reader.cc:385] T b06bbf78eaa44dd097880909de0bfbad: removed 2 log segments from log reader
I20260812 06:18:16.417044 25305 log.cc:1079] T b06bbf78eaa44dd097880909de0bfbad P bf6f9d63bcc6497195faf94d2405d297: Deleting log segment in path: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515490379373-24798-0/minicluster-data/ts-0-root/wals/b06bbf78eaa44dd097880909de0bfbad/wal-000000001 (ops 1-6)
I20260812 06:18:16.417086 25305 log.cc:1079] T b06bbf78eaa44dd097880909de0bfbad P bf6f9d63bcc6497195faf94d2405d297: Deleting log segment in path: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515490379373-24798-0/minicluster-data/ts-0-root/wals/b06bbf78eaa44dd097880909de0bfbad/wal-000000002 (ops 7-11)
I20260812 06:18:16.422081 25305 maintenance_manager.cc:643] P bf6f9d63bcc6497195faf94d2405d297: LogGCOp(b06bbf78eaa44dd097880909de0bfbad) complete. Timing: real 0.005s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:18:16.422403 25416 maintenance_manager.cc:419] P bf6f9d63bcc6497195faf94d2405d297: Scheduling UndoDeltaBlockGCOp(b06bbf78eaa44dd097880909de0bfbad): 16411398 bytes on disk
I20260812 06:18:16.422811 25305 maintenance_manager.cc:643] P bf6f9d63bcc6497195faf94d2405d297: UndoDeltaBlockGCOp(b06bbf78eaa44dd097880909de0bfbad) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4}
I20260812 06:18:16.423192 25416 maintenance_manager.cc:419] P bf6f9d63bcc6497195faf94d2405d297: Scheduling FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad): perf score=2.188937
I20260812 06:18:16.447741 25305 maintenance_manager.cc:643] P bf6f9d63bcc6497195faf94d2405d297: FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad) complete. Timing: real 0.024s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5918,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:16.448211 25416 maintenance_manager.cc:419] P bf6f9d63bcc6497195faf94d2405d297: Scheduling FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad): perf score=2.188937
I20260812 06:18:16.458418 25305 maintenance_manager.cc:643] P bf6f9d63bcc6497195faf94d2405d297: FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3976,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:16.458827 25416 maintenance_manager.cc:419] P bf6f9d63bcc6497195faf94d2405d297: Scheduling MajorDeltaCompactionOp(b06bbf78eaa44dd097880909de0bfbad): perf score=1.000000
I20260812 06:18:16.661414 25305 maintenance_manager.cc:643] P bf6f9d63bcc6497195faf94d2405d297: MajorDeltaCompactionOp(b06bbf78eaa44dd097880909de0bfbad) complete. Timing: real 0.202s	user 0.129s	sys 0.060s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774808,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":549,"lbm_read_time_us":13603,"lbm_reads_lt_1ms":569,"lbm_write_time_us":30200,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2688,"thread_start_us":308,"threads_started":5,"update_count":2500}
I20260812 06:18:16.661974 25416 maintenance_manager.cc:419] P bf6f9d63bcc6497195faf94d2405d297: Scheduling FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad): perf score=14.095187
I20260812 06:18:16.721325 25305 maintenance_manager.cc:643] P bf6f9d63bcc6497195faf94d2405d297: FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad) complete. Timing: real 0.059s	user 0.045s	sys 0.012s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":21526,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:16.721820 25416 maintenance_manager.cc:419] P bf6f9d63bcc6497195faf94d2405d297: Scheduling FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad): perf score=2.188937
I20260812 06:18:16.732366 25305 maintenance_manager.cc:643] P bf6f9d63bcc6497195faf94d2405d297: FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4118,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:16.732820 25416 maintenance_manager.cc:419] P bf6f9d63bcc6497195faf94d2405d297: Scheduling MajorDeltaCompactionOp(b06bbf78eaa44dd097880909de0bfbad): perf score=1.000000
I20260812 06:18:16.912909 25305 maintenance_manager.cc:643] P bf6f9d63bcc6497195faf94d2405d297: MajorDeltaCompactionOp(b06bbf78eaa44dd097880909de0bfbad) complete. Timing: real 0.180s	user 0.116s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":249,"lbm_read_time_us":13806,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27903,"lbm_writes_lt_1ms":543,"mutex_wait_us":49,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9088,"update_count":2500}
I20260812 06:18:16.913556 25416 maintenance_manager.cc:419] P bf6f9d63bcc6497195faf94d2405d297: Scheduling FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad): perf score=11.118625
I20260812 06:18:16.947584 25305 maintenance_manager.cc:643] P bf6f9d63bcc6497195faf94d2405d297: FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad) complete. Timing: real 0.034s	user 0.018s	sys 0.012s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":14601,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:16.948180 25416 maintenance_manager.cc:419] P bf6f9d63bcc6497195faf94d2405d297: Scheduling FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad): perf score=2.188937
I20260812 06:18:16.962353 25305 maintenance_manager.cc:643] P bf6f9d63bcc6497195faf94d2405d297: FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5548,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:16.963017 25416 maintenance_manager.cc:419] P bf6f9d63bcc6497195faf94d2405d297: Scheduling MajorDeltaCompactionOp(b06bbf78eaa44dd097880909de0bfbad): perf score=1.000000
I20260812 06:18:17.138198 25305 maintenance_manager.cc:643] P bf6f9d63bcc6497195faf94d2405d297: MajorDeltaCompactionOp(b06bbf78eaa44dd097880909de0bfbad) complete. Timing: real 0.175s	user 0.096s	sys 0.065s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672269,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":226,"lbm_read_time_us":10734,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24699,"lbm_writes_lt_1ms":443,"mutex_wait_us":75,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12544,"update_count":2000}
I20260812 06:18:17.138938 25416 maintenance_manager.cc:419] P bf6f9d63bcc6497195faf94d2405d297: Scheduling FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad): perf score=14.095187
I20260812 06:18:17.196713 25305 maintenance_manager.cc:643] P bf6f9d63bcc6497195faf94d2405d297: FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad) complete. Timing: real 0.057s	user 0.033s	sys 0.023s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":25734,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:17.197225 25416 maintenance_manager.cc:419] P bf6f9d63bcc6497195faf94d2405d297: Scheduling FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad): perf score=2.188937
I20260812 06:18:17.209288 25305 maintenance_manager.cc:643] P bf6f9d63bcc6497195faf94d2405d297: FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad) complete. Timing: real 0.012s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4511,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:17.209944 25416 maintenance_manager.cc:419] P bf6f9d63bcc6497195faf94d2405d297: Scheduling MajorDeltaCompactionOp(b06bbf78eaa44dd097880909de0bfbad): perf score=1.000000
I20260812 06:18:17.377527 25305 maintenance_manager.cc:643] P bf6f9d63bcc6497195faf94d2405d297: MajorDeltaCompactionOp(b06bbf78eaa44dd097880909de0bfbad) complete. Timing: real 0.167s	user 0.138s	sys 0.021s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774692,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":968,"lbm_read_time_us":12931,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32097,"lbm_writes_lt_1ms":543,"mutex_wait_us":51,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5120,"update_count":2500}
I20260812 06:18:17.378221 25416 maintenance_manager.cc:419] P bf6f9d63bcc6497195faf94d2405d297: Scheduling FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad): perf score=14.095187
I20260812 06:18:17.429133 25305 maintenance_manager.cc:643] P bf6f9d63bcc6497195faf94d2405d297: FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad) complete. Timing: real 0.051s	user 0.028s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20235,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:17.429677 25416 maintenance_manager.cc:419] P bf6f9d63bcc6497195faf94d2405d297: Scheduling FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad): perf score=2.188937
I20260812 06:18:17.441059 25305 maintenance_manager.cc:643] P bf6f9d63bcc6497195faf94d2405d297: FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4069,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:17.441533 25416 maintenance_manager.cc:419] P bf6f9d63bcc6497195faf94d2405d297: Scheduling MajorDeltaCompactionOp(b06bbf78eaa44dd097880909de0bfbad): perf score=1.000000
I20260812 06:18:17.603665 25305 maintenance_manager.cc:643] P bf6f9d63bcc6497195faf94d2405d297: MajorDeltaCompactionOp(b06bbf78eaa44dd097880909de0bfbad) complete. Timing: real 0.162s	user 0.133s	sys 0.012s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":613,"lbm_read_time_us":10816,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29196,"lbm_writes_lt_1ms":543,"mutex_wait_us":70,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":27776,"update_count":2500}
I20260812 06:18:17.604499 25416 maintenance_manager.cc:419] P bf6f9d63bcc6497195faf94d2405d297: Scheduling FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad): perf score=14.095187
I20260812 06:18:17.654325 25305 maintenance_manager.cc:643] P bf6f9d63bcc6497195faf94d2405d297: FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad) complete. Timing: real 0.050s	user 0.027s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22893,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:17.654853 25416 maintenance_manager.cc:419] P bf6f9d63bcc6497195faf94d2405d297: Scheduling FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad): perf score=2.188937
I20260812 06:18:17.667088 25305 maintenance_manager.cc:643] P bf6f9d63bcc6497195faf94d2405d297: FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4257,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:17.667574 25416 maintenance_manager.cc:419] P bf6f9d63bcc6497195faf94d2405d297: Scheduling FlushMRSOp(b06bbf78eaa44dd097880909de0bfbad): perf score=1.000000
I20260812 06:18:17.694810 25305 maintenance_manager.cc:643] P bf6f9d63bcc6497195faf94d2405d297: FlushMRSOp(b06bbf78eaa44dd097880909de0bfbad) complete. Timing: real 0.027s	user 0.025s	sys 0.000s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":156,"dirs.run_cpu_time_us":209,"dirs.run_wall_time_us":1190,"drs_written":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1902,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:17.695464 25416 maintenance_manager.cc:419] P bf6f9d63bcc6497195faf94d2405d297: Scheduling LogGCOp(b06bbf78eaa44dd097880909de0bfbad): free 120553374 bytes of WAL
I20260812 06:18:17.695709 25305 log_reader.cc:385] T b06bbf78eaa44dd097880909de0bfbad: removed 12 log segments from log reader
I20260812 06:18:17.695755 25305 log.cc:1079] T b06bbf78eaa44dd097880909de0bfbad P bf6f9d63bcc6497195faf94d2405d297: Deleting log segment in path: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515490379373-24798-0/minicluster-data/ts-0-root/wals/b06bbf78eaa44dd097880909de0bfbad/wal-000000003 (ops 12-16)
I20260812 06:18:17.695784 25305 log.cc:1079] T b06bbf78eaa44dd097880909de0bfbad P bf6f9d63bcc6497195faf94d2405d297: Deleting log segment in path: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515490379373-24798-0/minicluster-data/ts-0-root/wals/b06bbf78eaa44dd097880909de0bfbad/wal-000000004 (ops 17-20)
I20260812 06:18:17.695847 25305 log.cc:1079] T b06bbf78eaa44dd097880909de0bfbad P bf6f9d63bcc6497195faf94d2405d297: Deleting log segment in path: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515490379373-24798-0/minicluster-data/ts-0-root/wals/b06bbf78eaa44dd097880909de0bfbad/wal-000000005 (ops 21-25)
I20260812 06:18:17.695878 25305 log.cc:1079] T b06bbf78eaa44dd097880909de0bfbad P bf6f9d63bcc6497195faf94d2405d297: Deleting log segment in path: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515490379373-24798-0/minicluster-data/ts-0-root/wals/b06bbf78eaa44dd097880909de0bfbad/wal-000000006 (ops 26-30)
I20260812 06:18:17.695912 25305 log.cc:1079] T b06bbf78eaa44dd097880909de0bfbad P bf6f9d63bcc6497195faf94d2405d297: Deleting log segment in path: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515490379373-24798-0/minicluster-data/ts-0-root/wals/b06bbf78eaa44dd097880909de0bfbad/wal-000000007 (ops 31-34)
I20260812 06:18:17.695941 25305 log.cc:1079] T b06bbf78eaa44dd097880909de0bfbad P bf6f9d63bcc6497195faf94d2405d297: Deleting log segment in path: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515490379373-24798-0/minicluster-data/ts-0-root/wals/b06bbf78eaa44dd097880909de0bfbad/wal-000000008 (ops 35-39)
I20260812 06:18:17.695976 25305 log.cc:1079] T b06bbf78eaa44dd097880909de0bfbad P bf6f9d63bcc6497195faf94d2405d297: Deleting log segment in path: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515490379373-24798-0/minicluster-data/ts-0-root/wals/b06bbf78eaa44dd097880909de0bfbad/wal-000000009 (ops 40-44)
I20260812 06:18:17.696012 25305 log.cc:1079] T b06bbf78eaa44dd097880909de0bfbad P bf6f9d63bcc6497195faf94d2405d297: Deleting log segment in path: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515490379373-24798-0/minicluster-data/ts-0-root/wals/b06bbf78eaa44dd097880909de0bfbad/wal-000000010 (ops 45-49)
I20260812 06:18:17.696048 25305 log.cc:1079] T b06bbf78eaa44dd097880909de0bfbad P bf6f9d63bcc6497195faf94d2405d297: Deleting log segment in path: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515490379373-24798-0/minicluster-data/ts-0-root/wals/b06bbf78eaa44dd097880909de0bfbad/wal-000000011 (ops 50-54)
I20260812 06:18:17.696086 25305 log.cc:1079] T b06bbf78eaa44dd097880909de0bfbad P bf6f9d63bcc6497195faf94d2405d297: Deleting log segment in path: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515490379373-24798-0/minicluster-data/ts-0-root/wals/b06bbf78eaa44dd097880909de0bfbad/wal-000000012 (ops 55-59)
I20260812 06:18:17.696125 25305 log.cc:1079] T b06bbf78eaa44dd097880909de0bfbad P bf6f9d63bcc6497195faf94d2405d297: Deleting log segment in path: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515490379373-24798-0/minicluster-data/ts-0-root/wals/b06bbf78eaa44dd097880909de0bfbad/wal-000000013 (ops 60-64)
I20260812 06:18:17.696190 25305 log.cc:1079] T b06bbf78eaa44dd097880909de0bfbad P bf6f9d63bcc6497195faf94d2405d297: Deleting log segment in path: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515490379373-24798-0/minicluster-data/ts-0-root/wals/b06bbf78eaa44dd097880909de0bfbad/wal-000000014 (ops 65-69)
I20260812 06:18:17.723282 25305 maintenance_manager.cc:643] P bf6f9d63bcc6497195faf94d2405d297: LogGCOp(b06bbf78eaa44dd097880909de0bfbad) complete. Timing: real 0.028s	user 0.002s	sys 0.023s Metrics: {}
I20260812 06:18:17.723874 25416 maintenance_manager.cc:419] P bf6f9d63bcc6497195faf94d2405d297: Scheduling UndoDeltaBlockGCOp(b06bbf78eaa44dd097880909de0bfbad): 462 bytes on disk
I20260812 06:18:17.724390 25305 maintenance_manager.cc:643] P bf6f9d63bcc6497195faf94d2405d297: UndoDeltaBlockGCOp(b06bbf78eaa44dd097880909de0bfbad) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4}
I20260812 06:18:17.724941 25416 maintenance_manager.cc:419] P bf6f9d63bcc6497195faf94d2405d297: Scheduling FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad): perf score=4.173312
I20260812 06:18:17.739938 25305 maintenance_manager.cc:643] P bf6f9d63bcc6497195faf94d2405d297: FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad) complete. Timing: real 0.015s	user 0.006s	sys 0.007s Metrics: {"bytes_written":6153872,"delete_count":0,"lbm_write_time_us":6142,"lbm_writes_lt_1ms":153,"reinsert_count":0,"update_count":750}
I20260812 06:18:17.740366 25416 maintenance_manager.cc:419] P bf6f9d63bcc6497195faf94d2405d297: Scheduling FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad): perf score=1.000000
I20260812 06:18:17.749457 25305 maintenance_manager.cc:643] P bf6f9d63bcc6497195faf94d2405d297: FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad) complete. Timing: real 0.009s	user 0.007s	sys 0.001s Metrics: {"bytes_written":2051402,"delete_count":0,"lbm_write_time_us":2757,"lbm_writes_lt_1ms":53,"reinsert_count":0,"update_count":250}
I20260812 06:18:17.749854 25416 maintenance_manager.cc:419] P bf6f9d63bcc6497195faf94d2405d297: Scheduling MajorDeltaCompactionOp(b06bbf78eaa44dd097880909de0bfbad): perf score=1.000000
I20260812 06:18:17.954437 25305 maintenance_manager.cc:643] P bf6f9d63bcc6497195faf94d2405d297: MajorDeltaCompactionOp(b06bbf78eaa44dd097880909de0bfbad) complete. Timing: real 0.204s	user 0.148s	sys 0.054s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979701,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":389,"lbm_read_time_us":14269,"lbm_reads_lt_1ms":766,"lbm_write_time_us":35845,"lbm_writes_lt_1ms":743,"mutex_wait_us":18,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":20992,"thread_start_us":97,"threads_started":1,"update_count":3500}
I20260812 06:18:17.955173 25416 maintenance_manager.cc:419] P bf6f9d63bcc6497195faf94d2405d297: Scheduling FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad): perf score=18.063937
I20260812 06:18:18.018496 25305 maintenance_manager.cc:643] P bf6f9d63bcc6497195faf94d2405d297: FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad) complete. Timing: real 0.063s	user 0.044s	sys 0.017s Metrics: {"bytes_written":20512318,"delete_count":0,"lbm_write_time_us":28385,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:18.019079 25416 maintenance_manager.cc:419] P bf6f9d63bcc6497195faf94d2405d297: Scheduling FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad): perf score=2.188937
I20260812 06:18:18.038838 25305 maintenance_manager.cc:643] P bf6f9d63bcc6497195faf94d2405d297: FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad) complete. Timing: real 0.020s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5725,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:18.039264 25416 maintenance_manager.cc:419] P bf6f9d63bcc6497195faf94d2405d297: Scheduling FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad): perf score=2.188937
I20260812 06:18:18.049782 25305 maintenance_manager.cc:643] P bf6f9d63bcc6497195faf94d2405d297: FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad) complete. Timing: real 0.010s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4197,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:18.050206 25416 maintenance_manager.cc:419] P bf6f9d63bcc6497195faf94d2405d297: Scheduling MajorDeltaCompactionOp(b06bbf78eaa44dd097880909de0bfbad): perf score=1.000000
I20260812 06:18:18.240388 25305 maintenance_manager.cc:643] P bf6f9d63bcc6497195faf94d2405d297: MajorDeltaCompactionOp(b06bbf78eaa44dd097880909de0bfbad) complete. Timing: real 0.190s	user 0.133s	sys 0.056s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":32979634,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":835,"lbm_read_time_us":14637,"lbm_reads_lt_1ms":773,"lbm_write_time_us":40369,"lbm_writes_lt_1ms":743,"mutex_wait_us":318,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":28032,"update_count":3500}
I20260812 06:18:18.241127 25416 maintenance_manager.cc:419] P bf6f9d63bcc6497195faf94d2405d297: Scheduling FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad): perf score=14.095187
I20260812 06:18:18.289942 25305 maintenance_manager.cc:643] P bf6f9d63bcc6497195faf94d2405d297: FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad) complete. Timing: real 0.049s	user 0.039s	sys 0.008s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21527,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:18.290675 25416 maintenance_manager.cc:419] P bf6f9d63bcc6497195faf94d2405d297: Scheduling FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad): perf score=2.188937
I20260812 06:18:18.307101 25305 maintenance_manager.cc:643] P bf6f9d63bcc6497195faf94d2405d297: FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad) complete. Timing: real 0.016s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4954,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:18.307688 25416 maintenance_manager.cc:419] P bf6f9d63bcc6497195faf94d2405d297: Scheduling MajorDeltaCompactionOp(b06bbf78eaa44dd097880909de0bfbad): perf score=1.000000
I20260812 06:18:18.477551 25305 maintenance_manager.cc:643] P bf6f9d63bcc6497195faf94d2405d297: MajorDeltaCompactionOp(b06bbf78eaa44dd097880909de0bfbad) complete. Timing: real 0.170s	user 0.128s	sys 0.027s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":313,"lbm_read_time_us":9960,"lbm_reads_lt_1ms":564,"lbm_write_time_us":33800,"lbm_writes_lt_1ms":543,"mutex_wait_us":39,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3072,"update_count":2500}
I20260812 06:18:18.478199 25416 maintenance_manager.cc:419] P bf6f9d63bcc6497195faf94d2405d297: Scheduling FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad): perf score=14.095187
I20260812 06:18:18.539409 25305 maintenance_manager.cc:643] P bf6f9d63bcc6497195faf94d2405d297: FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad) complete. Timing: real 0.061s	user 0.015s	sys 0.032s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":22610,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:18.539894 25416 maintenance_manager.cc:419] P bf6f9d63bcc6497195faf94d2405d297: Scheduling FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad): perf score=2.188937
I20260812 06:18:18.555330 25305 maintenance_manager.cc:643] P bf6f9d63bcc6497195faf94d2405d297: FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5698,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:18.555971 25416 maintenance_manager.cc:419] P bf6f9d63bcc6497195faf94d2405d297: Scheduling MajorDeltaCompactionOp(b06bbf78eaa44dd097880909de0bfbad): perf score=1.000000
I20260812 06:18:18.744964 25305 maintenance_manager.cc:643] P bf6f9d63bcc6497195faf94d2405d297: MajorDeltaCompactionOp(b06bbf78eaa44dd097880909de0bfbad) complete. Timing: real 0.189s	user 0.123s	sys 0.063s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":246,"lbm_read_time_us":13557,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29500,"lbm_writes_lt_1ms":543,"mutex_wait_us":67,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8064,"update_count":2500}
I20260812 06:18:18.745466 25416 maintenance_manager.cc:419] P bf6f9d63bcc6497195faf94d2405d297: Scheduling FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad): perf score=14.095187
I20260812 06:18:18.805171 25305 maintenance_manager.cc:643] P bf6f9d63bcc6497195faf94d2405d297: FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad) complete. Timing: real 0.060s	user 0.034s	sys 0.012s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21019,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:18.805621 25416 maintenance_manager.cc:419] P bf6f9d63bcc6497195faf94d2405d297: Scheduling FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad): perf score=2.188937
I20260812 06:18:18.817198 25305 maintenance_manager.cc:643] P bf6f9d63bcc6497195faf94d2405d297: FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4112,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:18.817699 25416 maintenance_manager.cc:419] P bf6f9d63bcc6497195faf94d2405d297: Scheduling MajorDeltaCompactionOp(b06bbf78eaa44dd097880909de0bfbad): perf score=1.000000
I20260812 06:18:18.986457 25305 maintenance_manager.cc:643] P bf6f9d63bcc6497195faf94d2405d297: MajorDeltaCompactionOp(b06bbf78eaa44dd097880909de0bfbad) complete. Timing: real 0.169s	user 0.127s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1022,"lbm_read_time_us":12048,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28894,"lbm_writes_lt_1ms":543,"mutex_wait_us":39,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:18:18.987164 25416 maintenance_manager.cc:419] P bf6f9d63bcc6497195faf94d2405d297: Scheduling FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad): perf score=14.095187
I20260812 06:18:19.036270 25305 maintenance_manager.cc:643] P bf6f9d63bcc6497195faf94d2405d297: FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad) complete. Timing: real 0.049s	user 0.025s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21780,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:19.036782 25416 maintenance_manager.cc:419] P bf6f9d63bcc6497195faf94d2405d297: Scheduling FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad): perf score=2.188937
I20260812 06:18:19.048521 25305 maintenance_manager.cc:643] P bf6f9d63bcc6497195faf94d2405d297: FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4212,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:19.049000 25416 maintenance_manager.cc:419] P bf6f9d63bcc6497195faf94d2405d297: Scheduling FlushMRSOp(b06bbf78eaa44dd097880909de0bfbad): perf score=1.000000
I20260812 06:18:19.078467 25305 maintenance_manager.cc:643] P bf6f9d63bcc6497195faf94d2405d297: FlushMRSOp(b06bbf78eaa44dd097880909de0bfbad) complete. Timing: real 0.029s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":70,"dirs.run_cpu_time_us":182,"dirs.run_wall_time_us":1032,"drs_written":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1505,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:19.079063 25416 maintenance_manager.cc:419] P bf6f9d63bcc6497195faf94d2405d297: Scheduling LogGCOp(b06bbf78eaa44dd097880909de0bfbad): free 115943190 bytes of WAL
I20260812 06:18:19.079273 25305 log_reader.cc:385] T b06bbf78eaa44dd097880909de0bfbad: removed 11 log segments from log reader
I20260812 06:18:19.079331 25305 log.cc:1079] T b06bbf78eaa44dd097880909de0bfbad P bf6f9d63bcc6497195faf94d2405d297: Deleting log segment in path: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515490379373-24798-0/minicluster-data/ts-0-root/wals/b06bbf78eaa44dd097880909de0bfbad/wal-000000015 (ops 70-74)
I20260812 06:18:19.079382 25305 log.cc:1079] T b06bbf78eaa44dd097880909de0bfbad P bf6f9d63bcc6497195faf94d2405d297: Deleting log segment in path: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515490379373-24798-0/minicluster-data/ts-0-root/wals/b06bbf78eaa44dd097880909de0bfbad/wal-000000016 (ops 75-79)
I20260812 06:18:19.079438 25305 log.cc:1079] T b06bbf78eaa44dd097880909de0bfbad P bf6f9d63bcc6497195faf94d2405d297: Deleting log segment in path: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515490379373-24798-0/minicluster-data/ts-0-root/wals/b06bbf78eaa44dd097880909de0bfbad/wal-000000017 (ops 80-84)
I20260812 06:18:19.079487 25305 log.cc:1079] T b06bbf78eaa44dd097880909de0bfbad P bf6f9d63bcc6497195faf94d2405d297: Deleting log segment in path: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515490379373-24798-0/minicluster-data/ts-0-root/wals/b06bbf78eaa44dd097880909de0bfbad/wal-000000018 (ops 85-89)
I20260812 06:18:19.079527 25305 log.cc:1079] T b06bbf78eaa44dd097880909de0bfbad P bf6f9d63bcc6497195faf94d2405d297: Deleting log segment in path: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515490379373-24798-0/minicluster-data/ts-0-root/wals/b06bbf78eaa44dd097880909de0bfbad/wal-000000019 (ops 90-94)
I20260812 06:18:19.079564 25305 log.cc:1079] T b06bbf78eaa44dd097880909de0bfbad P bf6f9d63bcc6497195faf94d2405d297: Deleting log segment in path: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515490379373-24798-0/minicluster-data/ts-0-root/wals/b06bbf78eaa44dd097880909de0bfbad/wal-000000020 (ops 95-99)
I20260812 06:18:19.079602 25305 log.cc:1079] T b06bbf78eaa44dd097880909de0bfbad P bf6f9d63bcc6497195faf94d2405d297: Deleting log segment in path: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515490379373-24798-0/minicluster-data/ts-0-root/wals/b06bbf78eaa44dd097880909de0bfbad/wal-000000021 (ops 100-104)
I20260812 06:18:19.079638 25305 log.cc:1079] T b06bbf78eaa44dd097880909de0bfbad P bf6f9d63bcc6497195faf94d2405d297: Deleting log segment in path: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515490379373-24798-0/minicluster-data/ts-0-root/wals/b06bbf78eaa44dd097880909de0bfbad/wal-000000022 (ops 105-109)
I20260812 06:18:19.079674 25305 log.cc:1079] T b06bbf78eaa44dd097880909de0bfbad P bf6f9d63bcc6497195faf94d2405d297: Deleting log segment in path: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515490379373-24798-0/minicluster-data/ts-0-root/wals/b06bbf78eaa44dd097880909de0bfbad/wal-000000023 (ops 110-114)
I20260812 06:18:19.079710 25305 log.cc:1079] T b06bbf78eaa44dd097880909de0bfbad P bf6f9d63bcc6497195faf94d2405d297: Deleting log segment in path: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515490379373-24798-0/minicluster-data/ts-0-root/wals/b06bbf78eaa44dd097880909de0bfbad/wal-000000024 (ops 115-119)
I20260812 06:18:19.079747 25305 log.cc:1079] T b06bbf78eaa44dd097880909de0bfbad P bf6f9d63bcc6497195faf94d2405d297: Deleting log segment in path: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515490379373-24798-0/minicluster-data/ts-0-root/wals/b06bbf78eaa44dd097880909de0bfbad/wal-000000025 (ops 120-124)
I20260812 06:18:19.105022 25305 maintenance_manager.cc:643] P bf6f9d63bcc6497195faf94d2405d297: LogGCOp(b06bbf78eaa44dd097880909de0bfbad) complete. Timing: real 0.026s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:18:19.105456 25416 maintenance_manager.cc:419] P bf6f9d63bcc6497195faf94d2405d297: Scheduling FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad): perf score=2.188937
I20260812 06:18:19.120829 25305 maintenance_manager.cc:643] P bf6f9d63bcc6497195faf94d2405d297: FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad) complete. Timing: real 0.015s	user 0.005s	sys 0.006s Metrics: {"bytes_written":4225735,"delete_count":0,"lbm_write_time_us":4462,"lbm_writes_lt_1ms":106,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":515}
I20260812 06:18:19.121251 25416 maintenance_manager.cc:419] P bf6f9d63bcc6497195faf94d2405d297: Scheduling FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad): perf score=2.188937
I20260812 06:18:19.131488 25305 maintenance_manager.cc:643] P bf6f9d63bcc6497195faf94d2405d297: FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3979584,"delete_count":0,"lbm_write_time_us":3962,"lbm_writes_lt_1ms":100,"reinsert_count":0,"update_count":485}
I20260812 06:18:19.131901 25416 maintenance_manager.cc:419] P bf6f9d63bcc6497195faf94d2405d297: Scheduling MajorDeltaCompactionOp(b06bbf78eaa44dd097880909de0bfbad): perf score=1.000000
I20260812 06:18:19.356498 25305 maintenance_manager.cc:643] P bf6f9d63bcc6497195faf94d2405d297: MajorDeltaCompactionOp(b06bbf78eaa44dd097880909de0bfbad) complete. Timing: real 0.224s	user 0.144s	sys 0.067s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979750,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":4100,"dirs.run_cpu_time_us":447,"dirs.run_wall_time_us":3840,"lbm_read_time_us":15098,"lbm_reads_lt_1ms":774,"lbm_write_time_us":35999,"lbm_writes_lt_1ms":743,"mutex_wait_us":3580,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":24576,"thread_start_us":76,"threads_started":1,"update_count":3500}
I20260812 06:18:19.357208 25416 maintenance_manager.cc:419] P bf6f9d63bcc6497195faf94d2405d297: Scheduling UndoDeltaBlockGCOp(b06bbf78eaa44dd097880909de0bfbad): 463 bytes on disk
I20260812 06:18:19.357594 25305 maintenance_manager.cc:643] P bf6f9d63bcc6497195faf94d2405d297: UndoDeltaBlockGCOp(b06bbf78eaa44dd097880909de0bfbad) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4}
I20260812 06:18:19.358057 25416 maintenance_manager.cc:419] P bf6f9d63bcc6497195faf94d2405d297: Scheduling FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad): perf score=18.063937
I20260812 06:18:19.414294 25305 maintenance_manager.cc:643] P bf6f9d63bcc6497195faf94d2405d297: FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad) complete. Timing: real 0.056s	user 0.034s	sys 0.020s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":25367,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:19.414942 25416 maintenance_manager.cc:419] P bf6f9d63bcc6497195faf94d2405d297: Scheduling FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad): perf score=2.188937
I20260812 06:18:19.434665 25305 maintenance_manager.cc:643] P bf6f9d63bcc6497195faf94d2405d297: FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad) complete. Timing: real 0.019s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6881,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:19.435106 25416 maintenance_manager.cc:419] P bf6f9d63bcc6497195faf94d2405d297: Scheduling MajorDeltaCompactionOp(b06bbf78eaa44dd097880909de0bfbad): perf score=1.000000
I20260812 06:18:19.596690 25305 maintenance_manager.cc:643] P bf6f9d63bcc6497195faf94d2405d297: MajorDeltaCompactionOp(b06bbf78eaa44dd097880909de0bfbad) complete. Timing: real 0.161s	user 0.122s	sys 0.037s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877102,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":439,"lbm_read_time_us":12515,"lbm_reads_lt_1ms":664,"lbm_write_time_us":32357,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":642,"mutex_wait_us":3,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":13312,"update_count":3000}
I20260812 06:18:19.597437 25416 maintenance_manager.cc:419] P bf6f9d63bcc6497195faf94d2405d297: Scheduling FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad): perf score=14.095187
I20260812 06:18:19.644757 25305 maintenance_manager.cc:643] P bf6f9d63bcc6497195faf94d2405d297: FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad) complete. Timing: real 0.047s	user 0.021s	sys 0.025s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20128,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:19.645236 25416 maintenance_manager.cc:419] P bf6f9d63bcc6497195faf94d2405d297: Scheduling FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad): perf score=2.188937
I20260812 06:18:19.670073 25305 maintenance_manager.cc:643] P bf6f9d63bcc6497195faf94d2405d297: FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad) complete. Timing: real 0.025s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5332,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:19.670603 25416 maintenance_manager.cc:419] P bf6f9d63bcc6497195faf94d2405d297: Scheduling FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad): perf score=2.188937
I20260812 06:18:19.685046 25305 maintenance_manager.cc:643] P bf6f9d63bcc6497195faf94d2405d297: FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad) complete. Timing: real 0.014s	user 0.012s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5639,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:19.685547 25416 maintenance_manager.cc:419] P bf6f9d63bcc6497195faf94d2405d297: Scheduling MajorDeltaCompactionOp(b06bbf78eaa44dd097880909de0bfbad): perf score=1.000000
I20260812 06:18:19.850355 25305 maintenance_manager.cc:643] P bf6f9d63bcc6497195faf94d2405d297: MajorDeltaCompactionOp(b06bbf78eaa44dd097880909de0bfbad) complete. Timing: real 0.165s	user 0.113s	sys 0.049s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877219,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":158,"lbm_read_time_us":12325,"lbm_reads_lt_1ms":673,"lbm_write_time_us":33079,"lbm_writes_lt_1ms":643,"mutex_wait_us":64,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":3000}
I20260812 06:18:19.852484 25416 maintenance_manager.cc:419] P bf6f9d63bcc6497195faf94d2405d297: Scheduling FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad): perf score=14.095187
I20260812 06:18:19.903309 25305 maintenance_manager.cc:643] P bf6f9d63bcc6497195faf94d2405d297: FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad) complete. Timing: real 0.051s	user 0.027s	sys 0.020s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21289,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:19.903859 25416 maintenance_manager.cc:419] P bf6f9d63bcc6497195faf94d2405d297: Scheduling FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad): perf score=2.188937
I20260812 06:18:19.921525 25305 maintenance_manager.cc:643] P bf6f9d63bcc6497195faf94d2405d297: FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad) complete. Timing: real 0.017s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5727,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:19.922035 25416 maintenance_manager.cc:419] P bf6f9d63bcc6497195faf94d2405d297: Scheduling MajorDeltaCompactionOp(b06bbf78eaa44dd097880909de0bfbad): perf score=1.000000
I20260812 06:18:20.087525 25305 maintenance_manager.cc:643] P bf6f9d63bcc6497195faf94d2405d297: MajorDeltaCompactionOp(b06bbf78eaa44dd097880909de0bfbad) complete. Timing: real 0.165s	user 0.129s	sys 0.030s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":421,"lbm_read_time_us":8686,"lbm_reads_lt_1ms":564,"lbm_write_time_us":33941,"lbm_writes_lt_1ms":543,"mutex_wait_us":57,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2500}
I20260812 06:18:20.088464 25416 maintenance_manager.cc:419] P bf6f9d63bcc6497195faf94d2405d297: Scheduling FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad): perf score=14.095187
I20260812 06:18:20.148696 25305 maintenance_manager.cc:643] P bf6f9d63bcc6497195faf94d2405d297: FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad) complete. Timing: real 0.060s	user 0.032s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25641,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:20.149226 25416 maintenance_manager.cc:419] P bf6f9d63bcc6497195faf94d2405d297: Scheduling FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad): perf score=2.188937
I20260812 06:18:20.159255 25305 maintenance_manager.cc:643] P bf6f9d63bcc6497195faf94d2405d297: FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3983,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:20.159699 25416 maintenance_manager.cc:419] P bf6f9d63bcc6497195faf94d2405d297: Scheduling MajorDeltaCompactionOp(b06bbf78eaa44dd097880909de0bfbad): perf score=1.000000
I20260812 06:18:20.339208 25305 maintenance_manager.cc:643] P bf6f9d63bcc6497195faf94d2405d297: MajorDeltaCompactionOp(b06bbf78eaa44dd097880909de0bfbad) complete. Timing: real 0.179s	user 0.117s	sys 0.059s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":913,"lbm_read_time_us":12811,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28056,"lbm_writes_lt_1ms":543,"mutex_wait_us":340,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2500}
I20260812 06:18:20.339901 25416 maintenance_manager.cc:419] P bf6f9d63bcc6497195faf94d2405d297: Scheduling FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad): perf score=14.095187
I20260812 06:18:20.392094 25305 maintenance_manager.cc:643] P bf6f9d63bcc6497195faf94d2405d297: FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad) complete. Timing: real 0.052s	user 0.018s	sys 0.025s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21422,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:20.392659 25416 maintenance_manager.cc:419] P bf6f9d63bcc6497195faf94d2405d297: Scheduling FlushMRSOp(b06bbf78eaa44dd097880909de0bfbad): perf score=1.000000
I20260812 06:18:20.442811 25305 maintenance_manager.cc:643] P bf6f9d63bcc6497195faf94d2405d297: FlushMRSOp(b06bbf78eaa44dd097880909de0bfbad) complete. Timing: real 0.050s	user 0.027s	sys 0.001s Metrics: {"bytes_written":1193505,"cfile_init":1,"dirs.queue_time_us":85,"dirs.run_cpu_time_us":152,"dirs.run_wall_time_us":1158,"drs_written":1,"lbm_read_time_us":90,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2047,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:20.443509 25416 maintenance_manager.cc:419] P bf6f9d63bcc6497195faf94d2405d297: Scheduling LogGCOp(b06bbf78eaa44dd097880909de0bfbad): free 121006682 bytes of WAL
I20260812 06:18:20.443743 25305 log_reader.cc:385] T b06bbf78eaa44dd097880909de0bfbad: removed 12 log segments from log reader
I20260812 06:18:20.443790 25305 log.cc:1079] T b06bbf78eaa44dd097880909de0bfbad P bf6f9d63bcc6497195faf94d2405d297: Deleting log segment in path: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515490379373-24798-0/minicluster-data/ts-0-root/wals/b06bbf78eaa44dd097880909de0bfbad/wal-000000026 (ops 125-129)
I20260812 06:18:20.443818 25305 log.cc:1079] T b06bbf78eaa44dd097880909de0bfbad P bf6f9d63bcc6497195faf94d2405d297: Deleting log segment in path: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515490379373-24798-0/minicluster-data/ts-0-root/wals/b06bbf78eaa44dd097880909de0bfbad/wal-000000027 (ops 130-134)
I20260812 06:18:20.443871 25305 log.cc:1079] T b06bbf78eaa44dd097880909de0bfbad P bf6f9d63bcc6497195faf94d2405d297: Deleting log segment in path: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515490379373-24798-0/minicluster-data/ts-0-root/wals/b06bbf78eaa44dd097880909de0bfbad/wal-000000028 (ops 135-139)
I20260812 06:18:20.443915 25305 log.cc:1079] T b06bbf78eaa44dd097880909de0bfbad P bf6f9d63bcc6497195faf94d2405d297: Deleting log segment in path: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515490379373-24798-0/minicluster-data/ts-0-root/wals/b06bbf78eaa44dd097880909de0bfbad/wal-000000029 (ops 140-144)
I20260812 06:18:20.443967 25305 log.cc:1079] T b06bbf78eaa44dd097880909de0bfbad P bf6f9d63bcc6497195faf94d2405d297: Deleting log segment in path: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515490379373-24798-0/minicluster-data/ts-0-root/wals/b06bbf78eaa44dd097880909de0bfbad/wal-000000030 (ops 145-149)
I20260812 06:18:20.444020 25305 log.cc:1079] T b06bbf78eaa44dd097880909de0bfbad P bf6f9d63bcc6497195faf94d2405d297: Deleting log segment in path: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515490379373-24798-0/minicluster-data/ts-0-root/wals/b06bbf78eaa44dd097880909de0bfbad/wal-000000031 (ops 150-154)
I20260812 06:18:20.444041 25305 log.cc:1079] T b06bbf78eaa44dd097880909de0bfbad P bf6f9d63bcc6497195faf94d2405d297: Deleting log segment in path: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515490379373-24798-0/minicluster-data/ts-0-root/wals/b06bbf78eaa44dd097880909de0bfbad/wal-000000032 (ops 155-158)
I20260812 06:18:20.444099 25305 log.cc:1079] T b06bbf78eaa44dd097880909de0bfbad P bf6f9d63bcc6497195faf94d2405d297: Deleting log segment in path: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515490379373-24798-0/minicluster-data/ts-0-root/wals/b06bbf78eaa44dd097880909de0bfbad/wal-000000033 (ops 159-163)
I20260812 06:18:20.444142 25305 log.cc:1079] T b06bbf78eaa44dd097880909de0bfbad P bf6f9d63bcc6497195faf94d2405d297: Deleting log segment in path: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515490379373-24798-0/minicluster-data/ts-0-root/wals/b06bbf78eaa44dd097880909de0bfbad/wal-000000034 (ops 164-168)
I20260812 06:18:20.444218 25305 log.cc:1079] T b06bbf78eaa44dd097880909de0bfbad P bf6f9d63bcc6497195faf94d2405d297: Deleting log segment in path: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515490379373-24798-0/minicluster-data/ts-0-root/wals/b06bbf78eaa44dd097880909de0bfbad/wal-000000035 (ops 169-173)
I20260812 06:18:20.444258 25305 log.cc:1079] T b06bbf78eaa44dd097880909de0bfbad P bf6f9d63bcc6497195faf94d2405d297: Deleting log segment in path: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515490379373-24798-0/minicluster-data/ts-0-root/wals/b06bbf78eaa44dd097880909de0bfbad/wal-000000036 (ops 174-178)
I20260812 06:18:20.444303 25305 log.cc:1079] T b06bbf78eaa44dd097880909de0bfbad P bf6f9d63bcc6497195faf94d2405d297: Deleting log segment in path: /tmp/dist-test-tasktqRpB5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515490379373-24798-0/minicluster-data/ts-0-root/wals/b06bbf78eaa44dd097880909de0bfbad/wal-000000037 (ops 179-183)
I20260812 06:18:20.470928 25305 maintenance_manager.cc:643] P bf6f9d63bcc6497195faf94d2405d297: LogGCOp(b06bbf78eaa44dd097880909de0bfbad) complete. Timing: real 0.027s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:18:20.471500 25416 maintenance_manager.cc:419] P bf6f9d63bcc6497195faf94d2405d297: Scheduling UndoDeltaBlockGCOp(b06bbf78eaa44dd097880909de0bfbad): 462 bytes on disk
I20260812 06:18:20.471966 25305 maintenance_manager.cc:643] P bf6f9d63bcc6497195faf94d2405d297: UndoDeltaBlockGCOp(b06bbf78eaa44dd097880909de0bfbad) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":72,"lbm_reads_lt_1ms":4}
I20260812 06:18:20.473526 25416 maintenance_manager.cc:419] P bf6f9d63bcc6497195faf94d2405d297: Scheduling FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad): perf score=7.149875
I20260812 06:18:20.493340 25305 maintenance_manager.cc:643] P bf6f9d63bcc6497195faf94d2405d297: FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad) complete. Timing: real 0.020s	user 0.006s	sys 0.012s Metrics: {"bytes_written":8369175,"delete_count":0,"lbm_write_time_us":8657,"lbm_writes_lt_1ms":207,"reinsert_count":0,"update_count":1020}
I20260812 06:18:20.493752 25416 maintenance_manager.cc:419] P bf6f9d63bcc6497195faf94d2405d297: Scheduling FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad): perf score=2.188937
I20260812 06:18:20.509570 25305 maintenance_manager.cc:643] P bf6f9d63bcc6497195faf94d2405d297: FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad) complete. Timing: real 0.016s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3938558,"delete_count":0,"lbm_write_time_us":5203,"lbm_writes_lt_1ms":99,"reinsert_count":0,"update_count":480}
I20260812 06:18:20.510023 25416 maintenance_manager.cc:419] P bf6f9d63bcc6497195faf94d2405d297: Scheduling MajorDeltaCompactionOp(b06bbf78eaa44dd097880909de0bfbad): perf score=1.000000
I20260812 06:18:20.729202 25305 maintenance_manager.cc:643] P bf6f9d63bcc6497195faf94d2405d297: MajorDeltaCompactionOp(b06bbf78eaa44dd097880909de0bfbad) complete. Timing: real 0.219s	user 0.151s	sys 0.067s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":32979628,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1171,"lbm_read_time_us":14130,"lbm_reads_lt_1ms":769,"lbm_write_time_us":40882,"lbm_writes_lt_1ms":743,"mutex_wait_us":570,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":10368,"thread_start_us":75,"threads_started":1,"update_count":3500}
I20260812 06:18:20.729808 25416 maintenance_manager.cc:419] P bf6f9d63bcc6497195faf94d2405d297: Scheduling FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad): perf score=18.063937
I20260812 06:18:20.800340 25305 maintenance_manager.cc:643] P bf6f9d63bcc6497195faf94d2405d297: FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad) complete. Timing: real 0.070s	user 0.046s	sys 0.024s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":31063,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:20.800803 25416 maintenance_manager.cc:419] P bf6f9d63bcc6497195faf94d2405d297: Scheduling FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad): perf score=2.188937
I20260812 06:18:20.820439 24798 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.721s	user 1.784s	sys 0.124s
I20260812 06:18:20.821933 25305 maintenance_manager.cc:643] P bf6f9d63bcc6497195faf94d2405d297: FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad) complete. Timing: real 0.021s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6139,"lbm_writes_lt_1ms":103,"mutex_wait_us":45,"reinsert_count":0,"update_count":500}
I20260812 06:18:20.822474 25416 maintenance_manager.cc:419] P bf6f9d63bcc6497195faf94d2405d297: Scheduling FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad): perf score=2.188937
I20260812 06:18:20.832247 25305 maintenance_manager.cc:643] P bf6f9d63bcc6497195faf94d2405d297: FlushDeltaMemStoresOp(b06bbf78eaa44dd097880909de0bfbad) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4038,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":500}
I20260812 06:18:20.832710 25416 maintenance_manager.cc:419] P bf6f9d63bcc6497195faf94d2405d297: Scheduling MajorDeltaCompactionOp(b06bbf78eaa44dd097880909de0bfbad): perf score=1.000000
I20260812 06:18:20.875706 24798 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.055s	user 0.001s	sys 0.000s
I20260812 06:18:20.876358 24798 tablet_server.cc:179] TabletServer@127.24.55.129:0 shutting down...
I20260812 06:18:20.977032 25305 maintenance_manager.cc:643] P bf6f9d63bcc6497195faf94d2405d297: MajorDeltaCompactionOp(b06bbf78eaa44dd097880909de0bfbad) complete. Timing: real 0.144s	user 0.096s	sys 0.048s Metrics: {"cfile_cache_hit":361,"cfile_cache_hit_bytes":14731061,"cfile_cache_miss":372,"cfile_cache_miss_bytes":18248571,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1266,"lbm_read_time_us":6828,"lbm_reads_lt_1ms":404,"lbm_write_time_us":33327,"lbm_writes_lt_1ms":743,"mutex_wait_us":319,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":8448,"update_count":3500}
I20260812 06:18:20.977780 24798 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:20.978032 24798 tablet_replica.cc:333] T b06bbf78eaa44dd097880909de0bfbad P bf6f9d63bcc6497195faf94d2405d297: stopping tablet replica
I20260812 06:18:20.978165 24798 raft_consensus.cc:2243] T b06bbf78eaa44dd097880909de0bfbad P bf6f9d63bcc6497195faf94d2405d297 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:20.978349 24798 raft_consensus.cc:2272] T b06bbf78eaa44dd097880909de0bfbad P bf6f9d63bcc6497195faf94d2405d297 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:20.982035 24798 tablet_server.cc:196] TabletServer@127.24.55.129:0 shutdown complete.
I20260812 06:18:21.036741 24798 master.cc:562] Master@127.24.55.190:44453 shutting down...
I20260812 06:18:21.040033 24798 raft_consensus.cc:2243] T 00000000000000000000000000000000 P bdae10314c944030ad2a1c0a070ff03f [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:21.040251 24798 raft_consensus.cc:2272] T 00000000000000000000000000000000 P bdae10314c944030ad2a1c0a070ff03f [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:21.040345 24798 tablet_replica.cc:333] T 00000000000000000000000000000000 P bdae10314c944030ad2a1c0a070ff03f: stopping tablet replica
I20260812 06:18:21.052832 24798 master.cc:584] Master@127.24.55.190:44453 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5268 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10755 ms total)

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