[==========] 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:20:01.919171 30933 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.30.53.126:39393
I20260812 06:20:01.920284 30933 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:20:01.920885 30933 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:01.928303 30939 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:20:01.928275 30940 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:20:01.928561 30943 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:20:01.928337 30933 server_base.cc:1061] running on GCE node
I20260812 06:20:01.929080 30933 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:01.929198 30933 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:20:01.929247 30933 hybrid_clock.cc:648] HybridClock initialized: now 1786515601929244 us; error 0 us; skew 500 ppm
I20260812 06:20:01.931105 30933 webserver.cc:533] Webserver started at http://127.30.53.126:33107/ using document root <none> and password file <none>
I20260812 06:20:01.931663 30933 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:01.931748 30933 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:01.932017 30933 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:01.933765 30933 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601908337-30933-0/minicluster-data/master-0-root/instance:
uuid: "d9484304aced4df09bf2b3ca9a52f4ef"
format_stamp: "Formatted at 2026-08-12 06:20:01 on dist-test-slave-1zqn"
I20260812 06:20:01.937341 30933 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.004s	sys 0.000s
I20260812 06:20:01.939473 30948 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:20:01.940559 30933 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.001s
I20260812 06:20:01.940697 30933 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601908337-30933-0/minicluster-data/master-0-root
uuid: "d9484304aced4df09bf2b3ca9a52f4ef"
format_stamp: "Formatted at 2026-08-12 06:20:01 on dist-test-slave-1zqn"
I20260812 06:20:01.940806 30933 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601908337-30933-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601908337-30933-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601908337-30933-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:20:01.959329 30933 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:01.960163 30933 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:20:01.960353 30933 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:01.968560 30933 rpc_server.cc:307] RPC server started. Bound to: 127.30.53.126:39393
I20260812 06:20:01.968623 31008 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.30.53.126:39393 every 8 connection(s)
I20260812 06:20:01.971038 31009 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:20:01.977087 31009 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P d9484304aced4df09bf2b3ca9a52f4ef: Bootstrap starting.
I20260812 06:20:01.979717 31009 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P d9484304aced4df09bf2b3ca9a52f4ef: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:01.980782 31009 log.cc:826] T 00000000000000000000000000000000 P d9484304aced4df09bf2b3ca9a52f4ef: Log is configured to *not* fsync() on all Append() calls
I20260812 06:20:01.982659 31009 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P d9484304aced4df09bf2b3ca9a52f4ef: No bootstrap required, opened a new log
I20260812 06:20:01.985502 31009 raft_consensus.cc:359] T 00000000000000000000000000000000 P d9484304aced4df09bf2b3ca9a52f4ef [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d9484304aced4df09bf2b3ca9a52f4ef" member_type: VOTER }
I20260812 06:20:01.985706 31009 raft_consensus.cc:385] T 00000000000000000000000000000000 P d9484304aced4df09bf2b3ca9a52f4ef [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:01.985790 31009 raft_consensus.cc:740] T 00000000000000000000000000000000 P d9484304aced4df09bf2b3ca9a52f4ef [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: d9484304aced4df09bf2b3ca9a52f4ef, State: Initialized, Role: FOLLOWER
I20260812 06:20:01.986416 31009 consensus_queue.cc:260] T 00000000000000000000000000000000 P d9484304aced4df09bf2b3ca9a52f4ef [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: "d9484304aced4df09bf2b3ca9a52f4ef" member_type: VOTER }
I20260812 06:20:01.986582 31009 raft_consensus.cc:399] T 00000000000000000000000000000000 P d9484304aced4df09bf2b3ca9a52f4ef [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:01.986685 31009 raft_consensus.cc:493] T 00000000000000000000000000000000 P d9484304aced4df09bf2b3ca9a52f4ef [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:01.986814 31009 raft_consensus.cc:3060] T 00000000000000000000000000000000 P d9484304aced4df09bf2b3ca9a52f4ef [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:01.987709 31009 raft_consensus.cc:515] T 00000000000000000000000000000000 P d9484304aced4df09bf2b3ca9a52f4ef [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d9484304aced4df09bf2b3ca9a52f4ef" member_type: VOTER }
I20260812 06:20:01.988200 31009 leader_election.cc:304] T 00000000000000000000000000000000 P d9484304aced4df09bf2b3ca9a52f4ef [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: d9484304aced4df09bf2b3ca9a52f4ef; no voters: 
I20260812 06:20:01.988557 31009 leader_election.cc:290] T 00000000000000000000000000000000 P d9484304aced4df09bf2b3ca9a52f4ef [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:01.988652 31012 raft_consensus.cc:2804] T 00000000000000000000000000000000 P d9484304aced4df09bf2b3ca9a52f4ef [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:01.989025 31012 raft_consensus.cc:697] T 00000000000000000000000000000000 P d9484304aced4df09bf2b3ca9a52f4ef [term 1 LEADER]: Becoming Leader. State: Replica: d9484304aced4df09bf2b3ca9a52f4ef, State: Running, Role: LEADER
I20260812 06:20:01.989470 31012 consensus_queue.cc:237] T 00000000000000000000000000000000 P d9484304aced4df09bf2b3ca9a52f4ef [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: "d9484304aced4df09bf2b3ca9a52f4ef" member_type: VOTER }
I20260812 06:20:01.989643 31009 sys_catalog.cc:565] T 00000000000000000000000000000000 P d9484304aced4df09bf2b3ca9a52f4ef [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:20:01.991461 31013 sys_catalog.cc:455] T 00000000000000000000000000000000 P d9484304aced4df09bf2b3ca9a52f4ef [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "d9484304aced4df09bf2b3ca9a52f4ef" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d9484304aced4df09bf2b3ca9a52f4ef" member_type: VOTER } }
I20260812 06:20:01.991470 31014 sys_catalog.cc:455] T 00000000000000000000000000000000 P d9484304aced4df09bf2b3ca9a52f4ef [sys.catalog]: SysCatalogTable state changed. Reason: New leader d9484304aced4df09bf2b3ca9a52f4ef. Latest consensus state: current_term: 1 leader_uuid: "d9484304aced4df09bf2b3ca9a52f4ef" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d9484304aced4df09bf2b3ca9a52f4ef" member_type: VOTER } }
I20260812 06:20:01.991603 31013 sys_catalog.cc:458] T 00000000000000000000000000000000 P d9484304aced4df09bf2b3ca9a52f4ef [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:01.991603 31014 sys_catalog.cc:458] T 00000000000000000000000000000000 P d9484304aced4df09bf2b3ca9a52f4ef [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:01.991981 30933 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:20:01.992226 31027 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:20:01.994364 31027 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:20:01.999523 31027 catalog_manager.cc:1383] Generated new cluster ID: 4bbf9e7a943b406a962cbaba1ac8eb7b
I20260812 06:20:01.999611 31027 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:20:02.018460 31027 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:20:02.019430 31027 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:20:02.028795 31027 catalog_manager.cc:6092] T 00000000000000000000000000000000 P d9484304aced4df09bf2b3ca9a52f4ef: Generated new TSK 0
I20260812 06:20:02.029549 31027 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:20:02.057116 30933 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:02.060340 31035 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:20:02.060423 31037 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:20:02.060618 31039 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:20:02.061008 30933 server_base.cc:1061] running on GCE node
I20260812 06:20:02.061292 30933 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:02.061340 30933 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:20:02.061357 30933 hybrid_clock.cc:648] HybridClock initialized: now 1786515602061358 us; error 0 us; skew 500 ppm
I20260812 06:20:02.062332 30933 webserver.cc:533] Webserver started at http://127.30.53.65:34153/ using document root <none> and password file <none>
I20260812 06:20:02.062568 30933 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:02.062623 30933 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:02.062731 30933 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:02.063145 30933 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601908337-30933-0/minicluster-data/ts-0-root/instance:
uuid: "44c11023a1ea4c7bb858d2dbc0b9edae"
format_stamp: "Formatted at 2026-08-12 06:20:02 on dist-test-slave-1zqn"
I20260812 06:20:02.064826 30933 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:20:02.065881 31050 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:20:02.066128 30933 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:20:02.066228 30933 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601908337-30933-0/minicluster-data/ts-0-root
uuid: "44c11023a1ea4c7bb858d2dbc0b9edae"
format_stamp: "Formatted at 2026-08-12 06:20:02 on dist-test-slave-1zqn"
I20260812 06:20:02.066318 30933 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601908337-30933-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601908337-30933-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601908337-30933-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:20:02.085328 30933 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:02.086124 30933 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:02.086738 30933 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:20:02.087636 30933 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:20:02.087716 30933 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:02.087795 30933 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:20:02.087831 30933 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:02.094920 30933 rpc_server.cc:307] RPC server started. Bound to: 127.30.53.65:34485
I20260812 06:20:02.095105 31129 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.30.53.65:34485 every 8 connection(s)
I20260812 06:20:02.105986 31130 heartbeater.cc:344] Connected to a master server at 127.30.53.126:39393
I20260812 06:20:02.106278 31130 heartbeater.cc:461] Registering TS with master...
I20260812 06:20:02.106745 31130 heartbeater.cc:507] Master 127.30.53.126:39393 requested a full tablet report, sending...
I20260812 06:20:02.108364 30966 ts_manager.cc:194] Registered new tserver with Master: 44c11023a1ea4c7bb858d2dbc0b9edae (127.30.53.65:34485)
I20260812 06:20:02.109136 30933 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.013462654s
I20260812 06:20:02.109860 30966 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:48172
I20260812 06:20:02.119616 30966 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:48178:
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:20:02.135345 31083 tablet_service.cc:1511] Processing CreateTablet for tablet 34a3cd3467924b1ca8ed37e73656f831 (DEFAULT_TABLE table=heavy-update-compaction-test [id=8c72f767e54d4c03b1be02c940623cd4]), partition=
I20260812 06:20:02.135815 31083 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 34a3cd3467924b1ca8ed37e73656f831. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:20:02.138209 31145 tablet_bootstrap.cc:492] T 34a3cd3467924b1ca8ed37e73656f831 P 44c11023a1ea4c7bb858d2dbc0b9edae: Bootstrap starting.
I20260812 06:20:02.139225 31145 tablet_bootstrap.cc:654] T 34a3cd3467924b1ca8ed37e73656f831 P 44c11023a1ea4c7bb858d2dbc0b9edae: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:02.140960 31145 tablet_bootstrap.cc:492] T 34a3cd3467924b1ca8ed37e73656f831 P 44c11023a1ea4c7bb858d2dbc0b9edae: No bootstrap required, opened a new log
I20260812 06:20:02.141088 31145 ts_tablet_manager.cc:1403] T 34a3cd3467924b1ca8ed37e73656f831 P 44c11023a1ea4c7bb858d2dbc0b9edae: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:20:02.141564 31145 raft_consensus.cc:359] T 34a3cd3467924b1ca8ed37e73656f831 P 44c11023a1ea4c7bb858d2dbc0b9edae [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "44c11023a1ea4c7bb858d2dbc0b9edae" member_type: VOTER last_known_addr { host: "127.30.53.65" port: 34485 } }
I20260812 06:20:02.141696 31145 raft_consensus.cc:385] T 34a3cd3467924b1ca8ed37e73656f831 P 44c11023a1ea4c7bb858d2dbc0b9edae [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:02.141750 31145 raft_consensus.cc:740] T 34a3cd3467924b1ca8ed37e73656f831 P 44c11023a1ea4c7bb858d2dbc0b9edae [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 44c11023a1ea4c7bb858d2dbc0b9edae, State: Initialized, Role: FOLLOWER
I20260812 06:20:02.141899 31145 consensus_queue.cc:260] T 34a3cd3467924b1ca8ed37e73656f831 P 44c11023a1ea4c7bb858d2dbc0b9edae [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: "44c11023a1ea4c7bb858d2dbc0b9edae" member_type: VOTER last_known_addr { host: "127.30.53.65" port: 34485 } }
I20260812 06:20:02.141995 31145 raft_consensus.cc:399] T 34a3cd3467924b1ca8ed37e73656f831 P 44c11023a1ea4c7bb858d2dbc0b9edae [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:02.142051 31145 raft_consensus.cc:493] T 34a3cd3467924b1ca8ed37e73656f831 P 44c11023a1ea4c7bb858d2dbc0b9edae [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:02.142113 31145 raft_consensus.cc:3060] T 34a3cd3467924b1ca8ed37e73656f831 P 44c11023a1ea4c7bb858d2dbc0b9edae [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:02.142841 31145 raft_consensus.cc:515] T 34a3cd3467924b1ca8ed37e73656f831 P 44c11023a1ea4c7bb858d2dbc0b9edae [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "44c11023a1ea4c7bb858d2dbc0b9edae" member_type: VOTER last_known_addr { host: "127.30.53.65" port: 34485 } }
I20260812 06:20:02.142998 31145 leader_election.cc:304] T 34a3cd3467924b1ca8ed37e73656f831 P 44c11023a1ea4c7bb858d2dbc0b9edae [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: 44c11023a1ea4c7bb858d2dbc0b9edae; no voters: 
I20260812 06:20:02.143252 31145 leader_election.cc:290] T 34a3cd3467924b1ca8ed37e73656f831 P 44c11023a1ea4c7bb858d2dbc0b9edae [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:02.143352 31147 raft_consensus.cc:2804] T 34a3cd3467924b1ca8ed37e73656f831 P 44c11023a1ea4c7bb858d2dbc0b9edae [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:02.143528 31147 raft_consensus.cc:697] T 34a3cd3467924b1ca8ed37e73656f831 P 44c11023a1ea4c7bb858d2dbc0b9edae [term 1 LEADER]: Becoming Leader. State: Replica: 44c11023a1ea4c7bb858d2dbc0b9edae, State: Running, Role: LEADER
I20260812 06:20:02.143671 31145 ts_tablet_manager.cc:1434] T 34a3cd3467924b1ca8ed37e73656f831 P 44c11023a1ea4c7bb858d2dbc0b9edae: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:20:02.143698 31147 consensus_queue.cc:237] T 34a3cd3467924b1ca8ed37e73656f831 P 44c11023a1ea4c7bb858d2dbc0b9edae [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: "44c11023a1ea4c7bb858d2dbc0b9edae" member_type: VOTER last_known_addr { host: "127.30.53.65" port: 34485 } }
I20260812 06:20:02.144095 31130 heartbeater.cc:499] Master 127.30.53.126:39393 was elected leader, sending a full tablet report...
I20260812 06:20:02.146893 30966 catalog_manager.cc:5719] T 34a3cd3467924b1ca8ed37e73656f831 P 44c11023a1ea4c7bb858d2dbc0b9edae reported cstate change: term changed from 0 to 1, leader changed from <none> to 44c11023a1ea4c7bb858d2dbc0b9edae (127.30.53.65). New cstate: current_term: 1 leader_uuid: "44c11023a1ea4c7bb858d2dbc0b9edae" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "44c11023a1ea4c7bb858d2dbc0b9edae" member_type: VOTER last_known_addr { host: "127.30.53.65" port: 34485 } health_report { overall_health: HEALTHY } } }
I20260812 06:20:02.212777 30933 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.056s	user 0.015s	sys 0.009s
I20260812 06:20:02.346208 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling FlushMRSOp(34a3cd3467924b1ca8ed37e73656f831): perf score=15.086190
I20260812 06:20:02.518152 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: FlushMRSOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.172s	user 0.132s	sys 0.036s Metrics: {"bytes_written":12840807,"cfile_init":1,"compiler_manager_pool.queue_time_us":218,"delete_count":0,"dirs.queue_time_us":46,"dirs.run_cpu_time_us":234,"dirs.run_wall_time_us":874,"drs_written":1,"lbm_read_time_us":72,"lbm_reads_lt_1ms":4,"lbm_write_time_us":41625,"lbm_writes_lt_1ms":680,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":402176,"thread_start_us":143,"threads_started":1,"update_count":1565}
I20260812 06:20:02.519436 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling LogGCOp(34a3cd3467924b1ca8ed37e73656f831): free 20743880 bytes of WAL
I20260812 06:20:02.519742 31055 log_reader.cc:385] T 34a3cd3467924b1ca8ed37e73656f831: removed 2 log segments from log reader
I20260812 06:20:02.519804 31055 log.cc:1079] T 34a3cd3467924b1ca8ed37e73656f831 P 44c11023a1ea4c7bb858d2dbc0b9edae: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/34a3cd3467924b1ca8ed37e73656f831/wal-000000001 (ops 1-6)
I20260812 06:20:02.519852 31055 log.cc:1079] T 34a3cd3467924b1ca8ed37e73656f831 P 44c11023a1ea4c7bb858d2dbc0b9edae: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/34a3cd3467924b1ca8ed37e73656f831/wal-000000002 (ops 7-11)
I20260812 06:20:02.525835 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: LogGCOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.006s	user 0.001s	sys 0.003s Metrics: {}
I20260812 06:20:02.526190 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling UndoDeltaBlockGCOp(34a3cd3467924b1ca8ed37e73656f831): 12719216 bytes on disk
I20260812 06:20:02.526875 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: UndoDeltaBlockGCOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":65,"lbm_reads_lt_1ms":4}
I20260812 06:20:02.527371 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831): perf score=5.165500
I20260812 06:20:02.550285 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.023s	user 0.007s	sys 0.012s Metrics: {"bytes_written":6441042,"delete_count":0,"lbm_write_time_us":8848,"lbm_writes_lt_1ms":160,"reinsert_count":0,"update_count":785}
I20260812 06:20:02.550900 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling MajorDeltaCompactionOp(34a3cd3467924b1ca8ed37e73656f831): perf score=1.000000
I20260812 06:20:02.713964 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: MajorDeltaCompactionOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.163s	user 0.115s	sys 0.044s Metrics: {"cfile_cache_miss":502,"cfile_cache_miss_bytes":23543971,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":797,"lbm_read_time_us":9077,"lbm_reads_lt_1ms":530,"lbm_write_time_us":28663,"lbm_writes_lt_1ms":513,"peak_mem_usage":58763698,"reinsert_count":0,"spinlock_wait_cycles":1280,"thread_start_us":344,"threads_started":5,"update_count":2350}
I20260812 06:20:02.714627 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831): perf score=11.118625
I20260812 06:20:02.758522 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.044s	user 0.021s	sys 0.013s Metrics: {"bytes_written":13127977,"delete_count":0,"lbm_write_time_us":16618,"lbm_writes_lt_1ms":323,"reinsert_count":0,"update_count":1600}
I20260812 06:20:02.759091 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831): perf score=2.188937
I20260812 06:20:02.775322 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.016s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6090,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:02.775950 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling MajorDeltaCompactionOp(34a3cd3467924b1ca8ed37e73656f831): perf score=1.000000
I20260812 06:20:02.909693 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: MajorDeltaCompactionOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.134s	user 0.104s	sys 0.029s Metrics: {"cfile_cache_miss":452,"cfile_cache_miss_bytes":21492763,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":992,"lbm_read_time_us":10263,"lbm_reads_lt_1ms":492,"lbm_write_time_us":24336,"lbm_writes_lt_1ms":463,"mutex_wait_us":303,"peak_mem_usage":52550412,"reinsert_count":0,"spinlock_wait_cycles":12416,"update_count":2100}
I20260812 06:20:02.910473 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831): perf score=10.126437
I20260812 06:20:02.952598 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.042s	user 0.030s	sys 0.011s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":19366,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:20:02.953109 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831): perf score=2.188937
I20260812 06:20:02.965310 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.012s	user 0.001s	sys 0.010s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4521,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:02.965759 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling MajorDeltaCompactionOp(34a3cd3467924b1ca8ed37e73656f831): perf score=1.000000
I20260812 06:20:03.097852 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: MajorDeltaCompactionOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.132s	user 0.082s	sys 0.049s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672275,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":185,"lbm_read_time_us":9459,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26167,"lbm_writes_lt_1ms":443,"mutex_wait_us":21,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12416,"update_count":2000}
I20260812 06:20:03.098469 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831): perf score=10.126437
I20260812 06:20:03.148205 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.050s	user 0.022s	sys 0.027s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":17385,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:20:03.148800 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831): perf score=2.188937
I20260812 06:20:03.166738 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.018s	user 0.014s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6799,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:03.167351 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling MajorDeltaCompactionOp(34a3cd3467924b1ca8ed37e73656f831): perf score=1.000000
I20260812 06:20:03.317118 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: MajorDeltaCompactionOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.150s	user 0.105s	sys 0.043s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":720,"lbm_read_time_us":10927,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25371,"lbm_writes_lt_1ms":443,"mutex_wait_us":297,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5760,"update_count":2000}
I20260812 06:20:03.317830 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831): perf score=10.126437
I20260812 06:20:03.368094 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.050s	user 0.028s	sys 0.010s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16358,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:03.368693 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831): perf score=2.188937
I20260812 06:20:03.386649 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.018s	user 0.014s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6748,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:03.387240 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling MajorDeltaCompactionOp(34a3cd3467924b1ca8ed37e73656f831): perf score=1.000000
I20260812 06:20:03.524308 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: MajorDeltaCompactionOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.137s	user 0.099s	sys 0.036s 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":1917,"lbm_read_time_us":10889,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25008,"lbm_writes_lt_1ms":443,"mutex_wait_us":1642,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":17536,"update_count":2000}
I20260812 06:20:03.525022 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831): perf score=10.126437
I20260812 06:20:03.572626 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.047s	user 0.028s	sys 0.005s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14572,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:03.573195 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831): perf score=2.188937
I20260812 06:20:03.586741 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.013s	user 0.010s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4724,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:03.587306 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling MajorDeltaCompactionOp(34a3cd3467924b1ca8ed37e73656f831): perf score=1.000000
I20260812 06:20:03.735800 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: MajorDeltaCompactionOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.148s	user 0.116s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":654,"lbm_read_time_us":11487,"lbm_reads_lt_1ms":468,"lbm_write_time_us":29366,"lbm_writes_lt_1ms":443,"mutex_wait_us":242,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6144,"update_count":2000}
I20260812 06:20:03.736431 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831): perf score=10.126437
I20260812 06:20:03.776288 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.040s	user 0.027s	sys 0.012s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":16815,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:03.776835 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831): perf score=2.188937
I20260812 06:20:03.792996 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.016s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6031,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:03.793620 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling FlushMRSOp(34a3cd3467924b1ca8ed37e73656f831): perf score=1.000000
I20260812 06:20:03.823395 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: FlushMRSOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.030s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":64,"dirs.run_cpu_time_us":267,"dirs.run_wall_time_us":1430,"drs_written":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1632,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:20:03.824434 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling LogGCOp(34a3cd3467924b1ca8ed37e73656f831): free 112692384 bytes of WAL
I20260812 06:20:03.824720 31055 log_reader.cc:385] T 34a3cd3467924b1ca8ed37e73656f831: removed 11 log segments from log reader
I20260812 06:20:03.824772 31055 log.cc:1079] T 34a3cd3467924b1ca8ed37e73656f831 P 44c11023a1ea4c7bb858d2dbc0b9edae: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/34a3cd3467924b1ca8ed37e73656f831/wal-000000003 (ops 12-16)
I20260812 06:20:03.824805 31055 log.cc:1079] T 34a3cd3467924b1ca8ed37e73656f831 P 44c11023a1ea4c7bb858d2dbc0b9edae: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/34a3cd3467924b1ca8ed37e73656f831/wal-000000004 (ops 17-21)
I20260812 06:20:03.824868 31055 log.cc:1079] T 34a3cd3467924b1ca8ed37e73656f831 P 44c11023a1ea4c7bb858d2dbc0b9edae: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/34a3cd3467924b1ca8ed37e73656f831/wal-000000005 (ops 22-26)
I20260812 06:20:03.824901 31055 log.cc:1079] T 34a3cd3467924b1ca8ed37e73656f831 P 44c11023a1ea4c7bb858d2dbc0b9edae: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/34a3cd3467924b1ca8ed37e73656f831/wal-000000006 (ops 27-31)
I20260812 06:20:03.824939 31055 log.cc:1079] T 34a3cd3467924b1ca8ed37e73656f831 P 44c11023a1ea4c7bb858d2dbc0b9edae: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/34a3cd3467924b1ca8ed37e73656f831/wal-000000007 (ops 32-36)
I20260812 06:20:03.824965 31055 log.cc:1079] T 34a3cd3467924b1ca8ed37e73656f831 P 44c11023a1ea4c7bb858d2dbc0b9edae: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/34a3cd3467924b1ca8ed37e73656f831/wal-000000008 (ops 37-41)
I20260812 06:20:03.824988 31055 log.cc:1079] T 34a3cd3467924b1ca8ed37e73656f831 P 44c11023a1ea4c7bb858d2dbc0b9edae: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/34a3cd3467924b1ca8ed37e73656f831/wal-000000009 (ops 42-46)
I20260812 06:20:03.825011 31055 log.cc:1079] T 34a3cd3467924b1ca8ed37e73656f831 P 44c11023a1ea4c7bb858d2dbc0b9edae: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/34a3cd3467924b1ca8ed37e73656f831/wal-000000010 (ops 47-51)
I20260812 06:20:03.825037 31055 log.cc:1079] T 34a3cd3467924b1ca8ed37e73656f831 P 44c11023a1ea4c7bb858d2dbc0b9edae: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/34a3cd3467924b1ca8ed37e73656f831/wal-000000011 (ops 52-56)
I20260812 06:20:03.825086 31055 log.cc:1079] T 34a3cd3467924b1ca8ed37e73656f831 P 44c11023a1ea4c7bb858d2dbc0b9edae: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/34a3cd3467924b1ca8ed37e73656f831/wal-000000012 (ops 57-61)
I20260812 06:20:03.825117 31055 log.cc:1079] T 34a3cd3467924b1ca8ed37e73656f831 P 44c11023a1ea4c7bb858d2dbc0b9edae: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/34a3cd3467924b1ca8ed37e73656f831/wal-000000013 (ops 62-66)
I20260812 06:20:03.851372 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: LogGCOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.027s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:20:03.851977 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling UndoDeltaBlockGCOp(34a3cd3467924b1ca8ed37e73656f831): 448 bytes on disk
I20260812 06:20:03.852632 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: UndoDeltaBlockGCOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":107,"lbm_reads_lt_1ms":4}
I20260812 06:20:03.853133 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831): perf score=3.181125
I20260812 06:20:03.868402 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.015s	user 0.006s	sys 0.007s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4936,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:03.868844 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831): perf score=2.188937
I20260812 06:20:03.878708 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3660,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:03.879154 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling MajorDeltaCompactionOp(34a3cd3467924b1ca8ed37e73656f831): perf score=1.000000
I20260812 06:20:04.061697 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: MajorDeltaCompactionOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.182s	user 0.149s	sys 0.023s 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":585,"lbm_read_time_us":11027,"lbm_reads_lt_1ms":674,"lbm_write_time_us":37362,"lbm_writes_lt_1ms":643,"mutex_wait_us":51,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":34944,"thread_start_us":79,"threads_started":1,"update_count":3000}
I20260812 06:20:04.062318 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831): perf score=14.095187
I20260812 06:20:04.114253 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.052s	user 0.024s	sys 0.024s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21343,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:04.114753 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831): perf score=2.188937
I20260812 06:20:04.126839 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4150,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:04.127537 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling MajorDeltaCompactionOp(34a3cd3467924b1ca8ed37e73656f831): perf score=1.000000
I20260812 06:20:04.282768 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: MajorDeltaCompactionOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.155s	user 0.113s	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":714,"lbm_read_time_us":9725,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30047,"lbm_writes_lt_1ms":543,"mutex_wait_us":393,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3712,"update_count":2500}
I20260812 06:20:04.283761 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831): perf score=11.118625
I20260812 06:20:04.321013 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.037s	user 0.033s	sys 0.003s Metrics: {"bytes_written":12512610,"delete_count":0,"lbm_write_time_us":16112,"lbm_writes_lt_1ms":308,"reinsert_count":0,"update_count":1525}
I20260812 06:20:04.321584 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831): perf score=2.188937
I20260812 06:20:04.337874 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.016s	user 0.010s	sys 0.004s Metrics: {"bytes_written":3897534,"delete_count":0,"lbm_write_time_us":6014,"lbm_writes_lt_1ms":98,"reinsert_count":0,"update_count":475}
I20260812 06:20:04.338466 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling MajorDeltaCompactionOp(34a3cd3467924b1ca8ed37e73656f831): perf score=1.000000
I20260812 06:20:04.498620 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: MajorDeltaCompactionOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.160s	user 0.119s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":605,"lbm_read_time_us":11406,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26278,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:20:04.499217 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831): perf score=11.118625
I20260812 06:20:04.541450 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.042s	user 0.021s	sys 0.019s Metrics: {"bytes_written":12717740,"delete_count":0,"lbm_write_time_us":18514,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:04.542002 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831): perf score=2.188937
I20260812 06:20:04.560767 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.019s	user 0.005s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5151,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:04.561264 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831): perf score=2.188937
I20260812 06:20:04.582324 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.021s	user 0.015s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4426,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:04.582877 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling MajorDeltaCompactionOp(34a3cd3467924b1ca8ed37e73656f831): perf score=1.000000
I20260812 06:20:04.773579 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: MajorDeltaCompactionOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.190s	user 0.118s	sys 0.060s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774803,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1082,"lbm_read_time_us":13229,"lbm_reads_lt_1ms":573,"lbm_write_time_us":28624,"lbm_writes_lt_1ms":543,"mutex_wait_us":101,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14976,"update_count":2500}
I20260812 06:20:04.774322 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831): perf score=14.095187
I20260812 06:20:04.823328 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.049s	user 0.028s	sys 0.011s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":18384,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:04.823938 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831): perf score=2.188937
I20260812 06:20:04.840807 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.017s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6319,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:04.841518 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling MajorDeltaCompactionOp(34a3cd3467924b1ca8ed37e73656f831): perf score=1.000000
I20260812 06:20:05.023376 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: MajorDeltaCompactionOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.182s	user 0.124s	sys 0.052s 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":895,"lbm_read_time_us":12555,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32344,"lbm_writes_lt_1ms":543,"mutex_wait_us":253,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2500}
I20260812 06:20:05.024044 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831): perf score=11.118625
I20260812 06:20:05.069679 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.045s	user 0.031s	sys 0.012s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":19842,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:20:05.070485 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831): perf score=2.188937
I20260812 06:20:05.083796 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.013s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4165,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:05.084404 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling MajorDeltaCompactionOp(34a3cd3467924b1ca8ed37e73656f831): perf score=1.000000
I20260812 06:20:05.219290 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: MajorDeltaCompactionOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.135s	user 0.090s	sys 0.044s 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":503,"lbm_read_time_us":8911,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26397,"lbm_writes_lt_1ms":443,"mutex_wait_us":91,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:20:05.220199 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831): perf score=10.126437
I20260812 06:20:05.264818 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.044s	user 0.032s	sys 0.004s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15857,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:05.265331 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831): perf score=2.188937
I20260812 06:20:05.276844 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4268,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:05.277733 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling FlushMRSOp(34a3cd3467924b1ca8ed37e73656f831): perf score=1.000000
I20260812 06:20:05.310756 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: FlushMRSOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.033s	user 0.024s	sys 0.007s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":70,"dirs.run_cpu_time_us":201,"dirs.run_wall_time_us":1285,"drs_written":1,"lbm_read_time_us":43,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1747,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:20:05.311494 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling LogGCOp(34a3cd3467924b1ca8ed37e73656f831): free 124257249 bytes of WAL
I20260812 06:20:05.311731 31055 log_reader.cc:385] T 34a3cd3467924b1ca8ed37e73656f831: removed 12 log segments from log reader
I20260812 06:20:05.311777 31055 log.cc:1079] T 34a3cd3467924b1ca8ed37e73656f831 P 44c11023a1ea4c7bb858d2dbc0b9edae: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/34a3cd3467924b1ca8ed37e73656f831/wal-000000014 (ops 67-71)
I20260812 06:20:05.311806 31055 log.cc:1079] T 34a3cd3467924b1ca8ed37e73656f831 P 44c11023a1ea4c7bb858d2dbc0b9edae: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/34a3cd3467924b1ca8ed37e73656f831/wal-000000015 (ops 72-76)
I20260812 06:20:05.311869 31055 log.cc:1079] T 34a3cd3467924b1ca8ed37e73656f831 P 44c11023a1ea4c7bb858d2dbc0b9edae: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/34a3cd3467924b1ca8ed37e73656f831/wal-000000016 (ops 77-80)
I20260812 06:20:05.311910 31055 log.cc:1079] T 34a3cd3467924b1ca8ed37e73656f831 P 44c11023a1ea4c7bb858d2dbc0b9edae: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/34a3cd3467924b1ca8ed37e73656f831/wal-000000017 (ops 81-85)
I20260812 06:20:05.311939 31055 log.cc:1079] T 34a3cd3467924b1ca8ed37e73656f831 P 44c11023a1ea4c7bb858d2dbc0b9edae: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/34a3cd3467924b1ca8ed37e73656f831/wal-000000018 (ops 86-90)
I20260812 06:20:05.311995 31055 log.cc:1079] T 34a3cd3467924b1ca8ed37e73656f831 P 44c11023a1ea4c7bb858d2dbc0b9edae: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/34a3cd3467924b1ca8ed37e73656f831/wal-000000019 (ops 91-95)
I20260812 06:20:05.312040 31055 log.cc:1079] T 34a3cd3467924b1ca8ed37e73656f831 P 44c11023a1ea4c7bb858d2dbc0b9edae: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/34a3cd3467924b1ca8ed37e73656f831/wal-000000020 (ops 96-100)
I20260812 06:20:05.312105 31055 log.cc:1079] T 34a3cd3467924b1ca8ed37e73656f831 P 44c11023a1ea4c7bb858d2dbc0b9edae: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/34a3cd3467924b1ca8ed37e73656f831/wal-000000021 (ops 101-105)
I20260812 06:20:05.312145 31055 log.cc:1079] T 34a3cd3467924b1ca8ed37e73656f831 P 44c11023a1ea4c7bb858d2dbc0b9edae: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/34a3cd3467924b1ca8ed37e73656f831/wal-000000022 (ops 106-110)
I20260812 06:20:05.312186 31055 log.cc:1079] T 34a3cd3467924b1ca8ed37e73656f831 P 44c11023a1ea4c7bb858d2dbc0b9edae: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/34a3cd3467924b1ca8ed37e73656f831/wal-000000023 (ops 111-115)
I20260812 06:20:05.312228 31055 log.cc:1079] T 34a3cd3467924b1ca8ed37e73656f831 P 44c11023a1ea4c7bb858d2dbc0b9edae: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/34a3cd3467924b1ca8ed37e73656f831/wal-000000024 (ops 116-120)
I20260812 06:20:05.312268 31055 log.cc:1079] T 34a3cd3467924b1ca8ed37e73656f831 P 44c11023a1ea4c7bb858d2dbc0b9edae: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/34a3cd3467924b1ca8ed37e73656f831/wal-000000025 (ops 121-125)
I20260812 06:20:05.339900 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: LogGCOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.028s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:20:05.340526 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831): perf score=3.181125
I20260812 06:20:05.354151 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.013s	user 0.008s	sys 0.004s Metrics: {"bytes_written":5251342,"delete_count":0,"lbm_write_time_us":5421,"lbm_writes_lt_1ms":131,"mutex_wait_us":103,"reinsert_count":0,"update_count":640}
I20260812 06:20:05.354641 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling UndoDeltaBlockGCOp(34a3cd3467924b1ca8ed37e73656f831): 462 bytes on disk
I20260812 06:20:05.355103 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: UndoDeltaBlockGCOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4}
I20260812 06:20:05.355577 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831): perf score=1.196750
I20260812 06:20:05.366591 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":2953955,"delete_count":0,"lbm_write_time_us":3647,"lbm_writes_lt_1ms":75,"reinsert_count":0,"update_count":360}
I20260812 06:20:05.367089 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling MajorDeltaCompactionOp(34a3cd3467924b1ca8ed37e73656f831): perf score=1.000000
I20260812 06:20:05.540346 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: MajorDeltaCompactionOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.173s	user 0.125s	sys 0.044s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877311,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1421,"lbm_read_time_us":13023,"lbm_reads_lt_1ms":666,"lbm_write_time_us":34227,"lbm_writes_lt_1ms":643,"mutex_wait_us":20,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":13440,"thread_start_us":78,"threads_started":1,"update_count":3000}
I20260812 06:20:05.541014 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831): perf score=14.095187
I20260812 06:20:05.597179 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.056s	user 0.038s	sys 0.012s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":22696,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:05.597679 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831): perf score=2.188937
I20260812 06:20:05.610016 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4216,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:05.610743 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling MajorDeltaCompactionOp(34a3cd3467924b1ca8ed37e73656f831): perf score=1.000000
I20260812 06:20:05.779516 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: MajorDeltaCompactionOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.169s	user 0.124s	sys 0.036s 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":430,"lbm_read_time_us":9683,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32424,"lbm_writes_lt_1ms":543,"mutex_wait_us":73,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7808,"update_count":2500}
I20260812 06:20:05.780449 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831): perf score=14.095187
I20260812 06:20:05.825239 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.045s	user 0.027s	sys 0.016s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":19965,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:05.825767 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling MajorDeltaCompactionOp(34a3cd3467924b1ca8ed37e73656f831): perf score=1.000000
I20260812 06:20:05.991817 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: MajorDeltaCompactionOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.166s	user 0.132s	sys 0.032s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672160,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":264,"lbm_read_time_us":11334,"lbm_reads_lt_1ms":467,"lbm_write_time_us":28923,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5504,"update_count":2000}
I20260812 06:20:05.992702 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831): perf score=11.118625
I20260812 06:20:06.031796 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.039s	user 0.027s	sys 0.008s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16408,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:06.032490 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831): perf score=2.188937
I20260812 06:20:06.045027 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.012s	user 0.006s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4777,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:06.045563 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling MajorDeltaCompactionOp(34a3cd3467924b1ca8ed37e73656f831): perf score=1.000000
I20260812 06:20:06.182564 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: MajorDeltaCompactionOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.137s	user 0.107s	sys 0.030s 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":637,"lbm_read_time_us":9940,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26016,"lbm_writes_lt_1ms":443,"mutex_wait_us":350,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":2000}
I20260812 06:20:06.183141 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831): perf score=10.126437
I20260812 06:20:06.216418 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.033s	user 0.015s	sys 0.015s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":13621,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:06.216904 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831): perf score=2.188937
I20260812 06:20:06.228683 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4533,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:06.229214 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling MajorDeltaCompactionOp(34a3cd3467924b1ca8ed37e73656f831): perf score=1.000000
I20260812 06:20:06.354578 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: MajorDeltaCompactionOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.125s	user 0.104s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672280,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1357,"lbm_read_time_us":10258,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22740,"lbm_writes_lt_1ms":443,"mutex_wait_us":40,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10368,"update_count":2000}
I20260812 06:20:06.355300 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831): perf score=10.126437
I20260812 06:20:06.401432 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.046s	user 0.029s	sys 0.011s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18329,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:06.401979 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831): perf score=2.188937
I20260812 06:20:06.413018 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4097,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:06.413663 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling MajorDeltaCompactionOp(34a3cd3467924b1ca8ed37e73656f831): perf score=1.000000
I20260812 06:20:06.543032 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: MajorDeltaCompactionOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.129s	user 0.113s	sys 0.016s 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":963,"lbm_read_time_us":9162,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24866,"lbm_writes_lt_1ms":443,"mutex_wait_us":341,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11136,"update_count":2000}
I20260812 06:20:06.543630 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831): perf score=10.126437
I20260812 06:20:06.600090 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.056s	user 0.017s	sys 0.027s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16057,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:06.600747 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831): perf score=2.188937
I20260812 06:20:06.611992 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4304,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:06.612529 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling MajorDeltaCompactionOp(34a3cd3467924b1ca8ed37e73656f831): perf score=1.000000
I20260812 06:20:06.763216 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: MajorDeltaCompactionOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.151s	user 0.115s	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":635,"lbm_read_time_us":11282,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23703,"lbm_writes_lt_1ms":443,"mutex_wait_us":164,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":16384,"update_count":2000}
I20260812 06:20:06.764129 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831): perf score=10.126437
I20260812 06:20:06.803722 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.039s	user 0.006s	sys 0.029s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16804,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:06.804283 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831): perf score=2.188937
I20260812 06:20:06.815042 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.011s	user 0.009s	sys 0.000s 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:20:06.815797 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling FlushMRSOp(34a3cd3467924b1ca8ed37e73656f831): perf score=1.000000
I20260812 06:20:06.850522 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: FlushMRSOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.034s	user 0.033s	sys 0.000s Metrics: {"bytes_written":1275445,"cfile_init":1,"dirs.queue_time_us":72,"dirs.run_cpu_time_us":191,"dirs.run_wall_time_us":1425,"drs_written":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1824,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:20:06.851202 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling LogGCOp(34a3cd3467924b1ca8ed37e73656f831): free 128414660 bytes of WAL
I20260812 06:20:06.851436 31055 log_reader.cc:385] T 34a3cd3467924b1ca8ed37e73656f831: removed 13 log segments from log reader
I20260812 06:20:06.851483 31055 log.cc:1079] T 34a3cd3467924b1ca8ed37e73656f831 P 44c11023a1ea4c7bb858d2dbc0b9edae: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/34a3cd3467924b1ca8ed37e73656f831/wal-000000026 (ops 126-130)
I20260812 06:20:06.851514 31055 log.cc:1079] T 34a3cd3467924b1ca8ed37e73656f831 P 44c11023a1ea4c7bb858d2dbc0b9edae: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/34a3cd3467924b1ca8ed37e73656f831/wal-000000027 (ops 131-134)
I20260812 06:20:06.851580 31055 log.cc:1079] T 34a3cd3467924b1ca8ed37e73656f831 P 44c11023a1ea4c7bb858d2dbc0b9edae: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/34a3cd3467924b1ca8ed37e73656f831/wal-000000028 (ops 135-139)
I20260812 06:20:06.851624 31055 log.cc:1079] T 34a3cd3467924b1ca8ed37e73656f831 P 44c11023a1ea4c7bb858d2dbc0b9edae: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/34a3cd3467924b1ca8ed37e73656f831/wal-000000029 (ops 140-144)
I20260812 06:20:06.851667 31055 log.cc:1079] T 34a3cd3467924b1ca8ed37e73656f831 P 44c11023a1ea4c7bb858d2dbc0b9edae: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/34a3cd3467924b1ca8ed37e73656f831/wal-000000030 (ops 145-149)
I20260812 06:20:06.851732 31055 log.cc:1079] T 34a3cd3467924b1ca8ed37e73656f831 P 44c11023a1ea4c7bb858d2dbc0b9edae: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/34a3cd3467924b1ca8ed37e73656f831/wal-000000031 (ops 150-154)
I20260812 06:20:06.851771 31055 log.cc:1079] T 34a3cd3467924b1ca8ed37e73656f831 P 44c11023a1ea4c7bb858d2dbc0b9edae: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/34a3cd3467924b1ca8ed37e73656f831/wal-000000032 (ops 155-158)
I20260812 06:20:06.851815 31055 log.cc:1079] T 34a3cd3467924b1ca8ed37e73656f831 P 44c11023a1ea4c7bb858d2dbc0b9edae: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/34a3cd3467924b1ca8ed37e73656f831/wal-000000033 (ops 159-163)
I20260812 06:20:06.851855 31055 log.cc:1079] T 34a3cd3467924b1ca8ed37e73656f831 P 44c11023a1ea4c7bb858d2dbc0b9edae: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/34a3cd3467924b1ca8ed37e73656f831/wal-000000034 (ops 164-168)
I20260812 06:20:06.851895 31055 log.cc:1079] T 34a3cd3467924b1ca8ed37e73656f831 P 44c11023a1ea4c7bb858d2dbc0b9edae: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/34a3cd3467924b1ca8ed37e73656f831/wal-000000035 (ops 169-172)
I20260812 06:20:06.851934 31055 log.cc:1079] T 34a3cd3467924b1ca8ed37e73656f831 P 44c11023a1ea4c7bb858d2dbc0b9edae: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/34a3cd3467924b1ca8ed37e73656f831/wal-000000036 (ops 173-177)
I20260812 06:20:06.851981 31055 log.cc:1079] T 34a3cd3467924b1ca8ed37e73656f831 P 44c11023a1ea4c7bb858d2dbc0b9edae: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/34a3cd3467924b1ca8ed37e73656f831/wal-000000037 (ops 178-182)
I20260812 06:20:06.852021 31055 log.cc:1079] T 34a3cd3467924b1ca8ed37e73656f831 P 44c11023a1ea4c7bb858d2dbc0b9edae: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/34a3cd3467924b1ca8ed37e73656f831/wal-000000038 (ops 183-186)
I20260812 06:20:06.880646 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: LogGCOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.029s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:20:06.881232 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831): perf score=4.173312
I20260812 06:20:06.905376 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.024s	user 0.003s	sys 0.020s Metrics: {"bytes_written":5497489,"delete_count":0,"lbm_write_time_us":6188,"lbm_writes_lt_1ms":137,"reinsert_count":0,"update_count":670}
I20260812 06:20:06.905907 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831): perf score=1.196750
I20260812 06:20:06.914059 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.008s	user 0.003s	sys 0.004s Metrics: {"bytes_written":2707805,"delete_count":0,"lbm_write_time_us":2889,"lbm_writes_lt_1ms":69,"reinsert_count":0,"update_count":330}
I20260812 06:20:06.914573 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling MajorDeltaCompactionOp(34a3cd3467924b1ca8ed37e73656f831): perf score=1.000000
I20260812 06:20:07.114135 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: MajorDeltaCompactionOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.199s	user 0.121s	sys 0.075s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877310,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":594,"lbm_read_time_us":14204,"lbm_reads_lt_1ms":674,"lbm_write_time_us":33219,"lbm_writes_lt_1ms":643,"mutex_wait_us":75,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":12544,"thread_start_us":78,"threads_started":1,"update_count":3000}
I20260812 06:20:07.114988 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling UndoDeltaBlockGCOp(34a3cd3467924b1ca8ed37e73656f831): 483 bytes on disk
I20260812 06:20:07.116325 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: UndoDeltaBlockGCOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":79,"lbm_reads_lt_1ms":4}
I20260812 06:20:07.117090 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831): perf score=14.095187
I20260812 06:20:07.182361 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.065s	user 0.039s	sys 0.019s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22283,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:07.182941 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831): perf score=2.188937
I20260812 06:20:07.193831 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: FlushDeltaMemStoresOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4261,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:07.194306 31132 maintenance_manager.cc:419] P 44c11023a1ea4c7bb858d2dbc0b9edae: Scheduling MajorDeltaCompactionOp(34a3cd3467924b1ca8ed37e73656f831): perf score=1.000000
I20260812 06:20:07.247833 30933 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.035s	user 1.852s	sys 0.143s
I20260812 06:20:07.326893 30933 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.078s	user 0.003s	sys 0.000s
I20260812 06:20:07.327725 30933 tablet_server.cc:179] TabletServer@127.30.53.65:0 shutting down...
I20260812 06:20:07.356571 31055 maintenance_manager.cc:643] P 44c11023a1ea4c7bb858d2dbc0b9edae: MajorDeltaCompactionOp(34a3cd3467924b1ca8ed37e73656f831) complete. Timing: real 0.162s	user 0.114s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":287,"lbm_read_time_us":13279,"lbm_reads_lt_1ms":568,"lbm_write_time_us":25496,"lbm_writes_lt_1ms":543,"mutex_wait_us":39,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14592,"update_count":2500}
I20260812 06:20:07.357322 30933 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:20:07.357728 30933 tablet_replica.cc:333] T 34a3cd3467924b1ca8ed37e73656f831 P 44c11023a1ea4c7bb858d2dbc0b9edae: stopping tablet replica
I20260812 06:20:07.357981 30933 raft_consensus.cc:2243] T 34a3cd3467924b1ca8ed37e73656f831 P 44c11023a1ea4c7bb858d2dbc0b9edae [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:07.358227 30933 raft_consensus.cc:2272] T 34a3cd3467924b1ca8ed37e73656f831 P 44c11023a1ea4c7bb858d2dbc0b9edae [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:07.375715 30933 tablet_server.cc:196] TabletServer@127.30.53.65:0 shutdown complete.
I20260812 06:20:07.404919 30933 master.cc:562] Master@127.30.53.126:39393 shutting down...
I20260812 06:20:07.408962 30933 raft_consensus.cc:2243] T 00000000000000000000000000000000 P d9484304aced4df09bf2b3ca9a52f4ef [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:07.409142 30933 raft_consensus.cc:2272] T 00000000000000000000000000000000 P d9484304aced4df09bf2b3ca9a52f4ef [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:07.409196 30933 tablet_replica.cc:333] T 00000000000000000000000000000000 P d9484304aced4df09bf2b3ca9a52f4ef: stopping tablet replica
I20260812 06:20:07.421509 30933 master.cc:584] Master@127.30.53.126:39393 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5594 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:20:07.528834 30933 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.30.53.126:37911
I20260812 06:20:07.529227 30933 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:07.531418 31170 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:20:07.531525 31171 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:20:07.531558 30933 server_base.cc:1061] running on GCE node
W20260812 06:20:07.531404 31173 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:20:07.531823 30933 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:07.531898 30933 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:20:07.531942 30933 hybrid_clock.cc:648] HybridClock initialized: now 1786515607531941 us; error 0 us; skew 500 ppm
I20260812 06:20:07.532847 30933 webserver.cc:533] Webserver started at http://127.30.53.126:44499/ using document root <none> and password file <none>
I20260812 06:20:07.533033 30933 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:07.533094 30933 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:07.533196 30933 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:07.533635 30933 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601908337-30933-0/minicluster-data/master-0-root/instance:
uuid: "775b00631c9e4f769ade064118ed4c62"
format_stamp: "Formatted at 2026-08-12 06:20:07 on dist-test-slave-1zqn"
I20260812 06:20:07.535243 30933 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:20:07.536340 31179 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:20:07.536653 30933 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:20:07.536741 30933 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601908337-30933-0/minicluster-data/master-0-root
uuid: "775b00631c9e4f769ade064118ed4c62"
format_stamp: "Formatted at 2026-08-12 06:20:07 on dist-test-slave-1zqn"
I20260812 06:20:07.536819 30933 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601908337-30933-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601908337-30933-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601908337-30933-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:20:07.544147 30933 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:07.544539 30933 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:07.549594 30933 rpc_server.cc:307] RPC server started. Bound to: 127.30.53.126:37911
I20260812 06:20:07.550482 31237 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.30.53.126:37911 every 8 connection(s)
I20260812 06:20:07.551038 31238 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:20:07.553098 31238 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 775b00631c9e4f769ade064118ed4c62: Bootstrap starting.
I20260812 06:20:07.553925 31238 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 775b00631c9e4f769ade064118ed4c62: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:07.555176 31238 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 775b00631c9e4f769ade064118ed4c62: No bootstrap required, opened a new log
I20260812 06:20:07.555598 31238 raft_consensus.cc:359] T 00000000000000000000000000000000 P 775b00631c9e4f769ade064118ed4c62 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "775b00631c9e4f769ade064118ed4c62" member_type: VOTER }
I20260812 06:20:07.555711 31238 raft_consensus.cc:385] T 00000000000000000000000000000000 P 775b00631c9e4f769ade064118ed4c62 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:07.555768 31238 raft_consensus.cc:740] T 00000000000000000000000000000000 P 775b00631c9e4f769ade064118ed4c62 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 775b00631c9e4f769ade064118ed4c62, State: Initialized, Role: FOLLOWER
I20260812 06:20:07.555962 31238 consensus_queue.cc:260] T 00000000000000000000000000000000 P 775b00631c9e4f769ade064118ed4c62 [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: "775b00631c9e4f769ade064118ed4c62" member_type: VOTER }
I20260812 06:20:07.556100 31238 raft_consensus.cc:399] T 00000000000000000000000000000000 P 775b00631c9e4f769ade064118ed4c62 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:07.556152 31238 raft_consensus.cc:493] T 00000000000000000000000000000000 P 775b00631c9e4f769ade064118ed4c62 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:07.556207 31238 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 775b00631c9e4f769ade064118ed4c62 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:07.556943 31238 raft_consensus.cc:515] T 00000000000000000000000000000000 P 775b00631c9e4f769ade064118ed4c62 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "775b00631c9e4f769ade064118ed4c62" member_type: VOTER }
I20260812 06:20:07.557099 31238 leader_election.cc:304] T 00000000000000000000000000000000 P 775b00631c9e4f769ade064118ed4c62 [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: 775b00631c9e4f769ade064118ed4c62; no voters: 
I20260812 06:20:07.557308 31238 leader_election.cc:290] T 00000000000000000000000000000000 P 775b00631c9e4f769ade064118ed4c62 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:07.557446 31241 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 775b00631c9e4f769ade064118ed4c62 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:07.557677 31241 raft_consensus.cc:697] T 00000000000000000000000000000000 P 775b00631c9e4f769ade064118ed4c62 [term 1 LEADER]: Becoming Leader. State: Replica: 775b00631c9e4f769ade064118ed4c62, State: Running, Role: LEADER
I20260812 06:20:07.557782 31238 sys_catalog.cc:565] T 00000000000000000000000000000000 P 775b00631c9e4f769ade064118ed4c62 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:20:07.557868 31241 consensus_queue.cc:237] T 00000000000000000000000000000000 P 775b00631c9e4f769ade064118ed4c62 [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: "775b00631c9e4f769ade064118ed4c62" member_type: VOTER }
I20260812 06:20:07.558363 31244 sys_catalog.cc:455] T 00000000000000000000000000000000 P 775b00631c9e4f769ade064118ed4c62 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 775b00631c9e4f769ade064118ed4c62. Latest consensus state: current_term: 1 leader_uuid: "775b00631c9e4f769ade064118ed4c62" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "775b00631c9e4f769ade064118ed4c62" member_type: VOTER } }
I20260812 06:20:07.558348 31243 sys_catalog.cc:455] T 00000000000000000000000000000000 P 775b00631c9e4f769ade064118ed4c62 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "775b00631c9e4f769ade064118ed4c62" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "775b00631c9e4f769ade064118ed4c62" member_type: VOTER } }
I20260812 06:20:07.558462 31244 sys_catalog.cc:458] T 00000000000000000000000000000000 P 775b00631c9e4f769ade064118ed4c62 [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:07.558473 31243 sys_catalog.cc:458] T 00000000000000000000000000000000 P 775b00631c9e4f769ade064118ed4c62 [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:07.559252 31249 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:20:07.560273 31249 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:20:07.560482 30933 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:20:07.562366 31249 catalog_manager.cc:1383] Generated new cluster ID: 809a7ac27be54500b0ee3ea1379a5a5d
I20260812 06:20:07.562455 31249 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:20:07.584770 31249 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:20:07.585317 31249 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:20:07.595978 31249 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 775b00631c9e4f769ade064118ed4c62: Generated new TSK 0
I20260812 06:20:07.596200 31249 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:20:07.625272 30933 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:07.627854 31264 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:20:07.627877 30933 server_base.cc:1061] running on GCE node
W20260812 06:20:07.628043 31266 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:20:07.627955 31268 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:20:07.628384 30933 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:07.628429 30933 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:20:07.628446 30933 hybrid_clock.cc:648] HybridClock initialized: now 1786515607628446 us; error 0 us; skew 500 ppm
I20260812 06:20:07.629297 30933 webserver.cc:533] Webserver started at http://127.30.53.65:38487/ using document root <none> and password file <none>
I20260812 06:20:07.629434 30933 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:07.629477 30933 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:07.629528 30933 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:07.629884 30933 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601908337-30933-0/minicluster-data/ts-0-root/instance:
uuid: "622c0f8959b74788a3a505b6acc75b6e"
format_stamp: "Formatted at 2026-08-12 06:20:07 on dist-test-slave-1zqn"
I20260812 06:20:07.631361 30933 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:20:07.632391 31275 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:20:07.632627 30933 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:20:07.632692 30933 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601908337-30933-0/minicluster-data/ts-0-root
uuid: "622c0f8959b74788a3a505b6acc75b6e"
format_stamp: "Formatted at 2026-08-12 06:20:07 on dist-test-slave-1zqn"
I20260812 06:20:07.632791 30933 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601908337-30933-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601908337-30933-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601908337-30933-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:20:07.653559 30933 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:07.654008 30933 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:07.654358 30933 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:20:07.654883 30933 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:20:07.654922 30933 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:07.654955 30933 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:20:07.655010 30933 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:07.659876 30933 rpc_server.cc:307] RPC server started. Bound to: 127.30.53.65:34983
I20260812 06:20:07.662149 31360 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.30.53.65:34983 every 8 connection(s)
I20260812 06:20:07.674408 31361 heartbeater.cc:344] Connected to a master server at 127.30.53.126:37911
I20260812 06:20:07.674582 31361 heartbeater.cc:461] Registering TS with master...
I20260812 06:20:07.674866 31361 heartbeater.cc:507] Master 127.30.53.126:37911 requested a full tablet report, sending...
I20260812 06:20:07.675582 31197 ts_manager.cc:194] Registered new tserver with Master: 622c0f8959b74788a3a505b6acc75b6e (127.30.53.65:34983)
I20260812 06:20:07.676448 31197 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:53890
I20260812 06:20:07.676503 30933 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.015731822s
I20260812 06:20:07.684329 31197 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:53892:
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:20:07.693509 31312 tablet_service.cc:1511] Processing CreateTablet for tablet 498b8d40c02e4483b6617319b8208f83 (DEFAULT_TABLE table=heavy-update-compaction-test [id=1ead8a59f59d427487bc119a6c61d013]), partition=
I20260812 06:20:07.693830 31312 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 498b8d40c02e4483b6617319b8208f83. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:20:07.695794 31374 tablet_bootstrap.cc:492] T 498b8d40c02e4483b6617319b8208f83 P 622c0f8959b74788a3a505b6acc75b6e: Bootstrap starting.
I20260812 06:20:07.696791 31374 tablet_bootstrap.cc:654] T 498b8d40c02e4483b6617319b8208f83 P 622c0f8959b74788a3a505b6acc75b6e: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:07.697870 31374 tablet_bootstrap.cc:492] T 498b8d40c02e4483b6617319b8208f83 P 622c0f8959b74788a3a505b6acc75b6e: No bootstrap required, opened a new log
I20260812 06:20:07.697944 31374 ts_tablet_manager.cc:1403] T 498b8d40c02e4483b6617319b8208f83 P 622c0f8959b74788a3a505b6acc75b6e: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:20:07.698273 31374 raft_consensus.cc:359] T 498b8d40c02e4483b6617319b8208f83 P 622c0f8959b74788a3a505b6acc75b6e [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "622c0f8959b74788a3a505b6acc75b6e" member_type: VOTER last_known_addr { host: "127.30.53.65" port: 34983 } }
I20260812 06:20:07.698362 31374 raft_consensus.cc:385] T 498b8d40c02e4483b6617319b8208f83 P 622c0f8959b74788a3a505b6acc75b6e [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:07.698385 31374 raft_consensus.cc:740] T 498b8d40c02e4483b6617319b8208f83 P 622c0f8959b74788a3a505b6acc75b6e [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 622c0f8959b74788a3a505b6acc75b6e, State: Initialized, Role: FOLLOWER
I20260812 06:20:07.698478 31374 consensus_queue.cc:260] T 498b8d40c02e4483b6617319b8208f83 P 622c0f8959b74788a3a505b6acc75b6e [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: "622c0f8959b74788a3a505b6acc75b6e" member_type: VOTER last_known_addr { host: "127.30.53.65" port: 34983 } }
I20260812 06:20:07.698568 31374 raft_consensus.cc:399] T 498b8d40c02e4483b6617319b8208f83 P 622c0f8959b74788a3a505b6acc75b6e [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:07.698635 31374 raft_consensus.cc:493] T 498b8d40c02e4483b6617319b8208f83 P 622c0f8959b74788a3a505b6acc75b6e [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:07.698691 31374 raft_consensus.cc:3060] T 498b8d40c02e4483b6617319b8208f83 P 622c0f8959b74788a3a505b6acc75b6e [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:07.699522 31374 raft_consensus.cc:515] T 498b8d40c02e4483b6617319b8208f83 P 622c0f8959b74788a3a505b6acc75b6e [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "622c0f8959b74788a3a505b6acc75b6e" member_type: VOTER last_known_addr { host: "127.30.53.65" port: 34983 } }
I20260812 06:20:07.699684 31374 leader_election.cc:304] T 498b8d40c02e4483b6617319b8208f83 P 622c0f8959b74788a3a505b6acc75b6e [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: 622c0f8959b74788a3a505b6acc75b6e; no voters: 
I20260812 06:20:07.699913 31374 leader_election.cc:290] T 498b8d40c02e4483b6617319b8208f83 P 622c0f8959b74788a3a505b6acc75b6e [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:07.700129 31376 raft_consensus.cc:2804] T 498b8d40c02e4483b6617319b8208f83 P 622c0f8959b74788a3a505b6acc75b6e [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:07.700377 31374 ts_tablet_manager.cc:1434] T 498b8d40c02e4483b6617319b8208f83 P 622c0f8959b74788a3a505b6acc75b6e: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:20:07.700395 31376 raft_consensus.cc:697] T 498b8d40c02e4483b6617319b8208f83 P 622c0f8959b74788a3a505b6acc75b6e [term 1 LEADER]: Becoming Leader. State: Replica: 622c0f8959b74788a3a505b6acc75b6e, State: Running, Role: LEADER
I20260812 06:20:07.700438 31361 heartbeater.cc:499] Master 127.30.53.126:37911 was elected leader, sending a full tablet report...
I20260812 06:20:07.700613 31376 consensus_queue.cc:237] T 498b8d40c02e4483b6617319b8208f83 P 622c0f8959b74788a3a505b6acc75b6e [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: "622c0f8959b74788a3a505b6acc75b6e" member_type: VOTER last_known_addr { host: "127.30.53.65" port: 34983 } }
I20260812 06:20:07.701973 31197 catalog_manager.cc:5719] T 498b8d40c02e4483b6617319b8208f83 P 622c0f8959b74788a3a505b6acc75b6e reported cstate change: term changed from 0 to 1, leader changed from <none> to 622c0f8959b74788a3a505b6acc75b6e (127.30.53.65). New cstate: current_term: 1 leader_uuid: "622c0f8959b74788a3a505b6acc75b6e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "622c0f8959b74788a3a505b6acc75b6e" member_type: VOTER last_known_addr { host: "127.30.53.65" port: 34983 } health_report { overall_health: HEALTHY } } }
I20260812 06:20:07.763320 30933 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.054s	user 0.016s	sys 0.006s
I20260812 06:20:07.912680 31362 maintenance_manager.cc:419] P 622c0f8959b74788a3a505b6acc75b6e: Scheduling FlushMRSOp(498b8d40c02e4483b6617319b8208f83): perf score=19.054940
I20260812 06:20:08.073107 31283 maintenance_manager.cc:643] P 622c0f8959b74788a3a505b6acc75b6e: FlushMRSOp(498b8d40c02e4483b6617319b8208f83) complete. Timing: real 0.160s	user 0.103s	sys 0.056s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":92,"dirs.run_cpu_time_us":192,"dirs.run_wall_time_us":967,"drs_written":1,"lbm_read_time_us":42,"lbm_reads_lt_1ms":4,"lbm_write_time_us":44372,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:20:08.074247 31362 maintenance_manager.cc:419] P 622c0f8959b74788a3a505b6acc75b6e: Scheduling LogGCOp(498b8d40c02e4483b6617319b8208f83): free 20290830 bytes of WAL
I20260812 06:20:08.074697 31283 log_reader.cc:385] T 498b8d40c02e4483b6617319b8208f83: removed 2 log segments from log reader
I20260812 06:20:08.074852 31283 log.cc:1079] T 498b8d40c02e4483b6617319b8208f83 P 622c0f8959b74788a3a505b6acc75b6e: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/498b8d40c02e4483b6617319b8208f83/wal-000000001 (ops 1-6)
I20260812 06:20:08.074991 31283 log.cc:1079] T 498b8d40c02e4483b6617319b8208f83 P 622c0f8959b74788a3a505b6acc75b6e: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/498b8d40c02e4483b6617319b8208f83/wal-000000002 (ops 7-10)
I20260812 06:20:08.081302 31283 maintenance_manager.cc:643] P 622c0f8959b74788a3a505b6acc75b6e: LogGCOp(498b8d40c02e4483b6617319b8208f83) complete. Timing: real 0.007s	user 0.000s	sys 0.005s Metrics: {}
I20260812 06:20:08.081802 31362 maintenance_manager.cc:419] P 622c0f8959b74788a3a505b6acc75b6e: Scheduling FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83): perf score=2.188937
I20260812 06:20:08.098814 31283 maintenance_manager.cc:643] P 622c0f8959b74788a3a505b6acc75b6e: FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83) complete. Timing: real 0.017s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5571,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:08.099524 31362 maintenance_manager.cc:419] P 622c0f8959b74788a3a505b6acc75b6e: Scheduling MajorDeltaCompactionOp(498b8d40c02e4483b6617319b8208f83): perf score=1.000000
I20260812 06:20:08.262897 31283 maintenance_manager.cc:643] P 622c0f8959b74788a3a505b6acc75b6e: MajorDeltaCompactionOp(498b8d40c02e4483b6617319b8208f83) complete. Timing: real 0.163s	user 0.106s	sys 0.057s 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":511,"lbm_read_time_us":10300,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25214,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":299,"threads_started":5,"update_count":2000}
I20260812 06:20:08.263513 31362 maintenance_manager.cc:419] P 622c0f8959b74788a3a505b6acc75b6e: Scheduling UndoDeltaBlockGCOp(498b8d40c02e4483b6617319b8208f83): 16411396 bytes on disk
I20260812 06:20:08.263892 31283 maintenance_manager.cc:643] P 622c0f8959b74788a3a505b6acc75b6e: UndoDeltaBlockGCOp(498b8d40c02e4483b6617319b8208f83) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4}
I20260812 06:20:08.264374 31362 maintenance_manager.cc:419] P 622c0f8959b74788a3a505b6acc75b6e: Scheduling FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83): perf score=14.095187
I20260812 06:20:08.315619 31283 maintenance_manager.cc:643] P 622c0f8959b74788a3a505b6acc75b6e: FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83) complete. Timing: real 0.051s	user 0.026s	sys 0.017s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20685,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:08.316218 31362 maintenance_manager.cc:419] P 622c0f8959b74788a3a505b6acc75b6e: Scheduling FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83): perf score=2.188937
I20260812 06:20:08.327397 31283 maintenance_manager.cc:643] P 622c0f8959b74788a3a505b6acc75b6e: FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83) complete. Timing: real 0.011s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4003,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:08.328150 31362 maintenance_manager.cc:419] P 622c0f8959b74788a3a505b6acc75b6e: Scheduling MajorDeltaCompactionOp(498b8d40c02e4483b6617319b8208f83): perf score=1.000000
I20260812 06:20:08.494503 31283 maintenance_manager.cc:643] P 622c0f8959b74788a3a505b6acc75b6e: MajorDeltaCompactionOp(498b8d40c02e4483b6617319b8208f83) complete. Timing: real 0.166s	user 0.136s	sys 0.020s 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":912,"lbm_read_time_us":11531,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31148,"lbm_writes_lt_1ms":543,"mutex_wait_us":244,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:20:08.495168 31362 maintenance_manager.cc:419] P 622c0f8959b74788a3a505b6acc75b6e: Scheduling FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83): perf score=14.095187
I20260812 06:20:08.547451 31283 maintenance_manager.cc:643] P 622c0f8959b74788a3a505b6acc75b6e: FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83) complete. Timing: real 0.052s	user 0.031s	sys 0.011s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20536,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:08.547945 31362 maintenance_manager.cc:419] P 622c0f8959b74788a3a505b6acc75b6e: Scheduling FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83): perf score=2.188937
I20260812 06:20:08.559543 31283 maintenance_manager.cc:643] P 622c0f8959b74788a3a505b6acc75b6e: FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83) complete. Timing: real 0.011s	user 0.010s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4143,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:08.560158 31362 maintenance_manager.cc:419] P 622c0f8959b74788a3a505b6acc75b6e: Scheduling MajorDeltaCompactionOp(498b8d40c02e4483b6617319b8208f83): perf score=1.000000
I20260812 06:20:08.712699 31283 maintenance_manager.cc:643] P 622c0f8959b74788a3a505b6acc75b6e: MajorDeltaCompactionOp(498b8d40c02e4483b6617319b8208f83) complete. Timing: real 0.152s	user 0.134s	sys 0.013s 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":138,"lbm_read_time_us":10953,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30291,"lbm_writes_lt_1ms":543,"mutex_wait_us":20,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":19968,"update_count":2500}
I20260812 06:20:08.713274 31362 maintenance_manager.cc:419] P 622c0f8959b74788a3a505b6acc75b6e: Scheduling FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83): perf score=14.095187
I20260812 06:20:08.762626 31283 maintenance_manager.cc:643] P 622c0f8959b74788a3a505b6acc75b6e: FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83) complete. Timing: real 0.049s	user 0.026s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21854,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:08.763247 31362 maintenance_manager.cc:419] P 622c0f8959b74788a3a505b6acc75b6e: Scheduling FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83): perf score=2.188937
I20260812 06:20:08.776451 31283 maintenance_manager.cc:643] P 622c0f8959b74788a3a505b6acc75b6e: FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83) complete. Timing: real 0.013s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4776,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:08.777277 31362 maintenance_manager.cc:419] P 622c0f8959b74788a3a505b6acc75b6e: Scheduling MajorDeltaCompactionOp(498b8d40c02e4483b6617319b8208f83): perf score=1.000000
I20260812 06:20:08.939211 31283 maintenance_manager.cc:643] P 622c0f8959b74788a3a505b6acc75b6e: MajorDeltaCompactionOp(498b8d40c02e4483b6617319b8208f83) complete. Timing: real 0.162s	user 0.128s	sys 0.019s 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":195,"lbm_read_time_us":10554,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31090,"lbm_writes_lt_1ms":543,"mutex_wait_us":2,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3584,"update_count":2500}
I20260812 06:20:08.939805 31362 maintenance_manager.cc:419] P 622c0f8959b74788a3a505b6acc75b6e: Scheduling FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83): perf score=14.095187
I20260812 06:20:08.993150 31283 maintenance_manager.cc:643] P 622c0f8959b74788a3a505b6acc75b6e: FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83) complete. Timing: real 0.053s	user 0.025s	sys 0.028s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":24969,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:20:08.993718 31362 maintenance_manager.cc:419] P 622c0f8959b74788a3a505b6acc75b6e: Scheduling FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83): perf score=2.188937
I20260812 06:20:09.009865 31283 maintenance_manager.cc:643] P 622c0f8959b74788a3a505b6acc75b6e: FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83) complete. Timing: real 0.016s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5884,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:09.010437 31362 maintenance_manager.cc:419] P 622c0f8959b74788a3a505b6acc75b6e: Scheduling MajorDeltaCompactionOp(498b8d40c02e4483b6617319b8208f83): perf score=1.000000
I20260812 06:20:09.173096 31283 maintenance_manager.cc:643] P 622c0f8959b74788a3a505b6acc75b6e: MajorDeltaCompactionOp(498b8d40c02e4483b6617319b8208f83) complete. Timing: real 0.162s	user 0.127s	sys 0.035s 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":815,"lbm_read_time_us":10556,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32542,"lbm_writes_lt_1ms":543,"mutex_wait_us":391,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2048,"update_count":2500}
I20260812 06:20:09.173686 31362 maintenance_manager.cc:419] P 622c0f8959b74788a3a505b6acc75b6e: Scheduling FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83): perf score=10.126437
I20260812 06:20:09.216982 31283 maintenance_manager.cc:643] P 622c0f8959b74788a3a505b6acc75b6e: FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83) complete. Timing: real 0.043s	user 0.030s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18829,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:20:09.217680 31362 maintenance_manager.cc:419] P 622c0f8959b74788a3a505b6acc75b6e: Scheduling FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83): perf score=2.188937
I20260812 06:20:09.247052 31283 maintenance_manager.cc:643] P 622c0f8959b74788a3a505b6acc75b6e: FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83) complete. Timing: real 0.029s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6105,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:09.247587 31362 maintenance_manager.cc:419] P 622c0f8959b74788a3a505b6acc75b6e: Scheduling FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83): perf score=2.188937
I20260812 06:20:09.258270 31283 maintenance_manager.cc:643] P 622c0f8959b74788a3a505b6acc75b6e: FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83) complete. Timing: real 0.010s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4024,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:09.258879 31362 maintenance_manager.cc:419] P 622c0f8959b74788a3a505b6acc75b6e: Scheduling FlushMRSOp(498b8d40c02e4483b6617319b8208f83): perf score=1.000000
I20260812 06:20:09.289625 31283 maintenance_manager.cc:643] P 622c0f8959b74788a3a505b6acc75b6e: FlushMRSOp(498b8d40c02e4483b6617319b8208f83) complete. Timing: real 0.031s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":90,"dirs.run_cpu_time_us":320,"dirs.run_wall_time_us":1585,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1522,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:20:09.290314 31362 maintenance_manager.cc:419] P 622c0f8959b74788a3a505b6acc75b6e: Scheduling LogGCOp(498b8d40c02e4483b6617319b8208f83): free 112692360 bytes of WAL
I20260812 06:20:09.290549 31283 log_reader.cc:385] T 498b8d40c02e4483b6617319b8208f83: removed 11 log segments from log reader
I20260812 06:20:09.290598 31283 log.cc:1079] T 498b8d40c02e4483b6617319b8208f83 P 622c0f8959b74788a3a505b6acc75b6e: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/498b8d40c02e4483b6617319b8208f83/wal-000000003 (ops 11-15)
I20260812 06:20:09.290629 31283 log.cc:1079] T 498b8d40c02e4483b6617319b8208f83 P 622c0f8959b74788a3a505b6acc75b6e: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/498b8d40c02e4483b6617319b8208f83/wal-000000004 (ops 16-20)
I20260812 06:20:09.290690 31283 log.cc:1079] T 498b8d40c02e4483b6617319b8208f83 P 622c0f8959b74788a3a505b6acc75b6e: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/498b8d40c02e4483b6617319b8208f83/wal-000000005 (ops 21-25)
I20260812 06:20:09.290721 31283 log.cc:1079] T 498b8d40c02e4483b6617319b8208f83 P 622c0f8959b74788a3a505b6acc75b6e: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/498b8d40c02e4483b6617319b8208f83/wal-000000006 (ops 26-30)
I20260812 06:20:09.290763 31283 log.cc:1079] T 498b8d40c02e4483b6617319b8208f83 P 622c0f8959b74788a3a505b6acc75b6e: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/498b8d40c02e4483b6617319b8208f83/wal-000000007 (ops 31-35)
I20260812 06:20:09.290800 31283 log.cc:1079] T 498b8d40c02e4483b6617319b8208f83 P 622c0f8959b74788a3a505b6acc75b6e: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/498b8d40c02e4483b6617319b8208f83/wal-000000008 (ops 36-40)
I20260812 06:20:09.290838 31283 log.cc:1079] T 498b8d40c02e4483b6617319b8208f83 P 622c0f8959b74788a3a505b6acc75b6e: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/498b8d40c02e4483b6617319b8208f83/wal-000000009 (ops 41-45)
I20260812 06:20:09.290876 31283 log.cc:1079] T 498b8d40c02e4483b6617319b8208f83 P 622c0f8959b74788a3a505b6acc75b6e: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/498b8d40c02e4483b6617319b8208f83/wal-000000010 (ops 46-50)
I20260812 06:20:09.290915 31283 log.cc:1079] T 498b8d40c02e4483b6617319b8208f83 P 622c0f8959b74788a3a505b6acc75b6e: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/498b8d40c02e4483b6617319b8208f83/wal-000000011 (ops 51-55)
I20260812 06:20:09.290953 31283 log.cc:1079] T 498b8d40c02e4483b6617319b8208f83 P 622c0f8959b74788a3a505b6acc75b6e: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/498b8d40c02e4483b6617319b8208f83/wal-000000012 (ops 56-60)
I20260812 06:20:09.290992 31283 log.cc:1079] T 498b8d40c02e4483b6617319b8208f83 P 622c0f8959b74788a3a505b6acc75b6e: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/498b8d40c02e4483b6617319b8208f83/wal-000000013 (ops 61-65)
I20260812 06:20:09.315155 31283 maintenance_manager.cc:643] P 622c0f8959b74788a3a505b6acc75b6e: LogGCOp(498b8d40c02e4483b6617319b8208f83) complete. Timing: real 0.025s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:20:09.315551 31362 maintenance_manager.cc:419] P 622c0f8959b74788a3a505b6acc75b6e: Scheduling UndoDeltaBlockGCOp(498b8d40c02e4483b6617319b8208f83): 462 bytes on disk
I20260812 06:20:09.316020 31283 maintenance_manager.cc:643] P 622c0f8959b74788a3a505b6acc75b6e: UndoDeltaBlockGCOp(498b8d40c02e4483b6617319b8208f83) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":69,"lbm_reads_lt_1ms":4}
I20260812 06:20:09.316540 31362 maintenance_manager.cc:419] P 622c0f8959b74788a3a505b6acc75b6e: Scheduling FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83): perf score=2.188937
I20260812 06:20:09.338508 31283 maintenance_manager.cc:643] P 622c0f8959b74788a3a505b6acc75b6e: FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83) complete. Timing: real 0.022s	user 0.011s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6300,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:09.339011 31362 maintenance_manager.cc:419] P 622c0f8959b74788a3a505b6acc75b6e: Scheduling FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83): perf score=2.188937
I20260812 06:20:09.349349 31283 maintenance_manager.cc:643] P 622c0f8959b74788a3a505b6acc75b6e: FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3901,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:09.350011 31362 maintenance_manager.cc:419] P 622c0f8959b74788a3a505b6acc75b6e: Scheduling MajorDeltaCompactionOp(498b8d40c02e4483b6617319b8208f83): perf score=1.000000
I20260812 06:20:09.572968 31283 maintenance_manager.cc:643] P 622c0f8959b74788a3a505b6acc75b6e: MajorDeltaCompactionOp(498b8d40c02e4483b6617319b8208f83) complete. Timing: real 0.223s	user 0.150s	sys 0.067s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979868,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":515,"lbm_read_time_us":15971,"lbm_reads_lt_1ms":775,"lbm_write_time_us":37620,"lbm_writes_lt_1ms":743,"mutex_wait_us":54,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":7552,"thread_start_us":82,"threads_started":1,"update_count":3500}
I20260812 06:20:09.573694 31362 maintenance_manager.cc:419] P 622c0f8959b74788a3a505b6acc75b6e: Scheduling FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83): perf score=18.063937
I20260812 06:20:09.636211 31283 maintenance_manager.cc:643] P 622c0f8959b74788a3a505b6acc75b6e: FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83) complete. Timing: real 0.062s	user 0.038s	sys 0.024s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":28456,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:20:09.636857 31362 maintenance_manager.cc:419] P 622c0f8959b74788a3a505b6acc75b6e: Scheduling FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83): perf score=2.188937
I20260812 06:20:09.657142 31283 maintenance_manager.cc:643] P 622c0f8959b74788a3a505b6acc75b6e: FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83) complete. Timing: real 0.020s	user 0.011s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6949,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:09.657614 31362 maintenance_manager.cc:419] P 622c0f8959b74788a3a505b6acc75b6e: Scheduling MajorDeltaCompactionOp(498b8d40c02e4483b6617319b8208f83): perf score=1.000000
I20260812 06:20:09.826139 31283 maintenance_manager.cc:643] P 622c0f8959b74788a3a505b6acc75b6e: MajorDeltaCompactionOp(498b8d40c02e4483b6617319b8208f83) complete. Timing: real 0.168s	user 0.130s	sys 0.038s 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":1083,"lbm_read_time_us":10946,"lbm_reads_lt_1ms":664,"lbm_write_time_us":35615,"lbm_writes_lt_1ms":643,"mutex_wait_us":293,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":4480,"update_count":3000}
I20260812 06:20:09.826808 31362 maintenance_manager.cc:419] P 622c0f8959b74788a3a505b6acc75b6e: Scheduling FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83): perf score=14.095187
I20260812 06:20:09.878157 31283 maintenance_manager.cc:643] P 622c0f8959b74788a3a505b6acc75b6e: FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83) complete. Timing: real 0.051s	user 0.031s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22292,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:09.878698 31362 maintenance_manager.cc:419] P 622c0f8959b74788a3a505b6acc75b6e: Scheduling FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83): perf score=2.188937
I20260812 06:20:09.895087 31283 maintenance_manager.cc:643] P 622c0f8959b74788a3a505b6acc75b6e: FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83) complete. Timing: real 0.016s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6090,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:09.895679 31362 maintenance_manager.cc:419] P 622c0f8959b74788a3a505b6acc75b6e: Scheduling MajorDeltaCompactionOp(498b8d40c02e4483b6617319b8208f83): perf score=1.000000
I20260812 06:20:10.061419 31283 maintenance_manager.cc:643] P 622c0f8959b74788a3a505b6acc75b6e: MajorDeltaCompactionOp(498b8d40c02e4483b6617319b8208f83) complete. Timing: real 0.166s	user 0.118s	sys 0.047s 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":204,"lbm_read_time_us":10859,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32702,"lbm_writes_lt_1ms":543,"mutex_wait_us":110,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3840,"update_count":2500}
I20260812 06:20:10.062377 31362 maintenance_manager.cc:419] P 622c0f8959b74788a3a505b6acc75b6e: Scheduling FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83): perf score=10.126437
I20260812 06:20:10.097051 31283 maintenance_manager.cc:643] P 622c0f8959b74788a3a505b6acc75b6e: FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83) complete. Timing: real 0.034s	user 0.018s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15535,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:10.097959 31362 maintenance_manager.cc:419] P 622c0f8959b74788a3a505b6acc75b6e: Scheduling FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83): perf score=2.188937
I20260812 06:20:10.115650 31283 maintenance_manager.cc:643] P 622c0f8959b74788a3a505b6acc75b6e: FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83) complete. Timing: real 0.017s	user 0.008s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6893,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:10.116256 31362 maintenance_manager.cc:419] P 622c0f8959b74788a3a505b6acc75b6e: Scheduling MajorDeltaCompactionOp(498b8d40c02e4483b6617319b8208f83): perf score=1.000000
I20260812 06:20:10.275156 31283 maintenance_manager.cc:643] P 622c0f8959b74788a3a505b6acc75b6e: MajorDeltaCompactionOp(498b8d40c02e4483b6617319b8208f83) complete. Timing: real 0.159s	user 0.083s	sys 0.065s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":277,"lbm_read_time_us":10461,"lbm_reads_lt_1ms":468,"lbm_write_time_us":24428,"lbm_writes_lt_1ms":443,"mutex_wait_us":28,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5888,"update_count":2000}
I20260812 06:20:10.275842 31362 maintenance_manager.cc:419] P 622c0f8959b74788a3a505b6acc75b6e: Scheduling FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83): perf score=14.095187
I20260812 06:20:10.338517 31283 maintenance_manager.cc:643] P 622c0f8959b74788a3a505b6acc75b6e: FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83) complete. Timing: real 0.062s	user 0.021s	sys 0.028s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23159,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:10.339210 31362 maintenance_manager.cc:419] P 622c0f8959b74788a3a505b6acc75b6e: Scheduling FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83): perf score=2.188937
I20260812 06:20:10.362408 31283 maintenance_manager.cc:643] P 622c0f8959b74788a3a505b6acc75b6e: FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83) complete. Timing: real 0.023s	user 0.010s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4444,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:10.363111 31362 maintenance_manager.cc:419] P 622c0f8959b74788a3a505b6acc75b6e: Scheduling MajorDeltaCompactionOp(498b8d40c02e4483b6617319b8208f83): perf score=1.000000
I20260812 06:20:10.568373 31283 maintenance_manager.cc:643] P 622c0f8959b74788a3a505b6acc75b6e: MajorDeltaCompactionOp(498b8d40c02e4483b6617319b8208f83) complete. Timing: real 0.205s	user 0.100s	sys 0.104s 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":301,"lbm_read_time_us":14035,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33098,"lbm_writes_lt_1ms":543,"mutex_wait_us":55,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":35968,"update_count":2500}
I20260812 06:20:10.569329 31362 maintenance_manager.cc:419] P 622c0f8959b74788a3a505b6acc75b6e: Scheduling FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83): perf score=10.126437
I20260812 06:20:10.623236 31283 maintenance_manager.cc:643] P 622c0f8959b74788a3a505b6acc75b6e: FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83) complete. Timing: real 0.054s	user 0.027s	sys 0.017s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20216,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:10.624009 31362 maintenance_manager.cc:419] P 622c0f8959b74788a3a505b6acc75b6e: Scheduling FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83): perf score=2.188937
I20260812 06:20:10.643973 31283 maintenance_manager.cc:643] P 622c0f8959b74788a3a505b6acc75b6e: FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83) complete. Timing: real 0.020s	user 0.017s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7403,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:10.644783 31362 maintenance_manager.cc:419] P 622c0f8959b74788a3a505b6acc75b6e: Scheduling MajorDeltaCompactionOp(498b8d40c02e4483b6617319b8208f83): perf score=1.000000
I20260812 06:20:10.809489 31283 maintenance_manager.cc:643] P 622c0f8959b74788a3a505b6acc75b6e: MajorDeltaCompactionOp(498b8d40c02e4483b6617319b8208f83) complete. Timing: real 0.163s	user 0.107s	sys 0.039s 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":1779,"lbm_read_time_us":10062,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29852,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":617,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8960,"update_count":2000}
I20260812 06:20:10.810211 31362 maintenance_manager.cc:419] P 622c0f8959b74788a3a505b6acc75b6e: Scheduling FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83): perf score=10.126437
I20260812 06:20:10.857985 31283 maintenance_manager.cc:643] P 622c0f8959b74788a3a505b6acc75b6e: FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83) complete. Timing: real 0.048s	user 0.027s	sys 0.017s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20093,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:20:10.858551 31362 maintenance_manager.cc:419] P 622c0f8959b74788a3a505b6acc75b6e: Scheduling FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83): perf score=2.188937
I20260812 06:20:10.869748 31283 maintenance_manager.cc:643] P 622c0f8959b74788a3a505b6acc75b6e: FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3992,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:10.870533 31362 maintenance_manager.cc:419] P 622c0f8959b74788a3a505b6acc75b6e: Scheduling FlushMRSOp(498b8d40c02e4483b6617319b8208f83): perf score=1.000000
I20260812 06:20:10.902619 31283 maintenance_manager.cc:643] P 622c0f8959b74788a3a505b6acc75b6e: FlushMRSOp(498b8d40c02e4483b6617319b8208f83) complete. Timing: real 0.032s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":73,"dirs.run_cpu_time_us":235,"dirs.run_wall_time_us":1411,"drs_written":1,"lbm_read_time_us":46,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1885,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:20:10.903342 31362 maintenance_manager.cc:419] P 622c0f8959b74788a3a505b6acc75b6e: Scheduling LogGCOp(498b8d40c02e4483b6617319b8208f83): free 128867446 bytes of WAL
I20260812 06:20:10.903635 31283 log_reader.cc:385] T 498b8d40c02e4483b6617319b8208f83: removed 13 log segments from log reader
I20260812 06:20:10.903685 31283 log.cc:1079] T 498b8d40c02e4483b6617319b8208f83 P 622c0f8959b74788a3a505b6acc75b6e: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/498b8d40c02e4483b6617319b8208f83/wal-000000014 (ops 66-70)
I20260812 06:20:10.903716 31283 log.cc:1079] T 498b8d40c02e4483b6617319b8208f83 P 622c0f8959b74788a3a505b6acc75b6e: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/498b8d40c02e4483b6617319b8208f83/wal-000000015 (ops 71-74)
I20260812 06:20:10.903761 31283 log.cc:1079] T 498b8d40c02e4483b6617319b8208f83 P 622c0f8959b74788a3a505b6acc75b6e: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/498b8d40c02e4483b6617319b8208f83/wal-000000016 (ops 75-79)
I20260812 06:20:10.903812 31283 log.cc:1079] T 498b8d40c02e4483b6617319b8208f83 P 622c0f8959b74788a3a505b6acc75b6e: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/498b8d40c02e4483b6617319b8208f83/wal-000000017 (ops 80-84)
I20260812 06:20:10.903834 31283 log.cc:1079] T 498b8d40c02e4483b6617319b8208f83 P 622c0f8959b74788a3a505b6acc75b6e: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/498b8d40c02e4483b6617319b8208f83/wal-000000018 (ops 85-89)
I20260812 06:20:10.903894 31283 log.cc:1079] T 498b8d40c02e4483b6617319b8208f83 P 622c0f8959b74788a3a505b6acc75b6e: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/498b8d40c02e4483b6617319b8208f83/wal-000000019 (ops 90-94)
I20260812 06:20:10.903960 31283 log.cc:1079] T 498b8d40c02e4483b6617319b8208f83 P 622c0f8959b74788a3a505b6acc75b6e: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/498b8d40c02e4483b6617319b8208f83/wal-000000020 (ops 95-98)
I20260812 06:20:10.904006 31283 log.cc:1079] T 498b8d40c02e4483b6617319b8208f83 P 622c0f8959b74788a3a505b6acc75b6e: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/498b8d40c02e4483b6617319b8208f83/wal-000000021 (ops 99-103)
I20260812 06:20:10.904073 31283 log.cc:1079] T 498b8d40c02e4483b6617319b8208f83 P 622c0f8959b74788a3a505b6acc75b6e: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/498b8d40c02e4483b6617319b8208f83/wal-000000022 (ops 104-108)
I20260812 06:20:10.904124 31283 log.cc:1079] T 498b8d40c02e4483b6617319b8208f83 P 622c0f8959b74788a3a505b6acc75b6e: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/498b8d40c02e4483b6617319b8208f83/wal-000000023 (ops 109-112)
I20260812 06:20:10.904170 31283 log.cc:1079] T 498b8d40c02e4483b6617319b8208f83 P 622c0f8959b74788a3a505b6acc75b6e: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/498b8d40c02e4483b6617319b8208f83/wal-000000024 (ops 113-117)
I20260812 06:20:10.904217 31283 log.cc:1079] T 498b8d40c02e4483b6617319b8208f83 P 622c0f8959b74788a3a505b6acc75b6e: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/498b8d40c02e4483b6617319b8208f83/wal-000000025 (ops 118-122)
I20260812 06:20:10.904261 31283 log.cc:1079] T 498b8d40c02e4483b6617319b8208f83 P 622c0f8959b74788a3a505b6acc75b6e: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/498b8d40c02e4483b6617319b8208f83/wal-000000026 (ops 123-127)
I20260812 06:20:10.935604 31283 maintenance_manager.cc:643] P 622c0f8959b74788a3a505b6acc75b6e: LogGCOp(498b8d40c02e4483b6617319b8208f83) complete. Timing: real 0.032s	user 0.002s	sys 0.027s Metrics: {}
I20260812 06:20:10.936156 31362 maintenance_manager.cc:419] P 622c0f8959b74788a3a505b6acc75b6e: Scheduling UndoDeltaBlockGCOp(498b8d40c02e4483b6617319b8208f83): 472 bytes on disk
I20260812 06:20:10.936645 31283 maintenance_manager.cc:643] P 622c0f8959b74788a3a505b6acc75b6e: UndoDeltaBlockGCOp(498b8d40c02e4483b6617319b8208f83) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":65,"lbm_reads_lt_1ms":4}
I20260812 06:20:10.937191 31362 maintenance_manager.cc:419] P 622c0f8959b74788a3a505b6acc75b6e: Scheduling FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83): perf score=6.157687
I20260812 06:20:10.964418 31283 maintenance_manager.cc:643] P 622c0f8959b74788a3a505b6acc75b6e: FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83) complete. Timing: real 0.027s	user 0.009s	sys 0.017s Metrics: {"bytes_written":8205077,"delete_count":0,"lbm_write_time_us":11151,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:20:10.965075 31362 maintenance_manager.cc:419] P 622c0f8959b74788a3a505b6acc75b6e: Scheduling MajorDeltaCompactionOp(498b8d40c02e4483b6617319b8208f83): perf score=1.000000
I20260812 06:20:11.189324 31283 maintenance_manager.cc:643] P 622c0f8959b74788a3a505b6acc75b6e: MajorDeltaCompactionOp(498b8d40c02e4483b6617319b8208f83) complete. Timing: real 0.224s	user 0.184s	sys 0.036s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877220,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":3699,"lbm_read_time_us":13310,"lbm_reads_lt_1ms":665,"lbm_write_time_us":43456,"lbm_writes_lt_1ms":643,"mutex_wait_us":23,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":12672,"thread_start_us":88,"threads_started":1,"update_count":3000}
I20260812 06:20:11.190102 31362 maintenance_manager.cc:419] P 622c0f8959b74788a3a505b6acc75b6e: Scheduling FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83): perf score=18.063937
I20260812 06:20:11.253954 31283 maintenance_manager.cc:643] P 622c0f8959b74788a3a505b6acc75b6e: FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83) complete. Timing: real 0.064s	user 0.034s	sys 0.028s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":29049,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:20:11.254462 31362 maintenance_manager.cc:419] P 622c0f8959b74788a3a505b6acc75b6e: Scheduling FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83): perf score=2.188937
I20260812 06:20:11.273419 31283 maintenance_manager.cc:643] P 622c0f8959b74788a3a505b6acc75b6e: FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83) complete. Timing: real 0.019s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5032,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:11.273886 31362 maintenance_manager.cc:419] P 622c0f8959b74788a3a505b6acc75b6e: Scheduling MajorDeltaCompactionOp(498b8d40c02e4483b6617319b8208f83): perf score=1.000000
I20260812 06:20:11.492285 31283 maintenance_manager.cc:643] P 622c0f8959b74788a3a505b6acc75b6e: MajorDeltaCompactionOp(498b8d40c02e4483b6617319b8208f83) complete. Timing: real 0.218s	user 0.156s	sys 0.058s 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":278,"lbm_read_time_us":13490,"lbm_reads_lt_1ms":664,"lbm_write_time_us":39524,"lbm_writes_lt_1ms":643,"mutex_wait_us":43,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":11136,"update_count":3000}
I20260812 06:20:11.492899 31362 maintenance_manager.cc:419] P 622c0f8959b74788a3a505b6acc75b6e: Scheduling FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83): perf score=14.095187
I20260812 06:20:11.545058 31283 maintenance_manager.cc:643] P 622c0f8959b74788a3a505b6acc75b6e: FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83) complete. Timing: real 0.052s	user 0.028s	sys 0.021s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21917,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:11.545696 31362 maintenance_manager.cc:419] P 622c0f8959b74788a3a505b6acc75b6e: Scheduling FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83): perf score=2.188937
I20260812 06:20:11.582139 31283 maintenance_manager.cc:643] P 622c0f8959b74788a3a505b6acc75b6e: FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83) complete. Timing: real 0.036s	user 0.008s	sys 0.015s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5730,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:11.582720 31362 maintenance_manager.cc:419] P 622c0f8959b74788a3a505b6acc75b6e: Scheduling FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83): perf score=2.188937
I20260812 06:20:11.593660 31283 maintenance_manager.cc:643] P 622c0f8959b74788a3a505b6acc75b6e: FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4165,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:11.594193 31362 maintenance_manager.cc:419] P 622c0f8959b74788a3a505b6acc75b6e: Scheduling MajorDeltaCompactionOp(498b8d40c02e4483b6617319b8208f83): perf score=1.000000
I20260812 06:20:11.811735 31283 maintenance_manager.cc:643] P 622c0f8959b74788a3a505b6acc75b6e: MajorDeltaCompactionOp(498b8d40c02e4483b6617319b8208f83) complete. Timing: real 0.217s	user 0.159s	sys 0.057s 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":470,"lbm_read_time_us":15531,"lbm_reads_lt_1ms":673,"lbm_write_time_us":35657,"lbm_writes_lt_1ms":643,"mutex_wait_us":624,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":3000}
I20260812 06:20:11.812983 31362 maintenance_manager.cc:419] P 622c0f8959b74788a3a505b6acc75b6e: Scheduling FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83): perf score=14.095187
I20260812 06:20:11.887363 31283 maintenance_manager.cc:643] P 622c0f8959b74788a3a505b6acc75b6e: FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83) complete. Timing: real 0.074s	user 0.040s	sys 0.022s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24870,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:11.887976 31362 maintenance_manager.cc:419] P 622c0f8959b74788a3a505b6acc75b6e: Scheduling FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83): perf score=3.181125
I20260812 06:20:11.899920 31283 maintenance_manager.cc:643] P 622c0f8959b74788a3a505b6acc75b6e: FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83) complete. Timing: real 0.012s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4591,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:11.900457 31362 maintenance_manager.cc:419] P 622c0f8959b74788a3a505b6acc75b6e: Scheduling FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83): perf score=2.188937
I20260812 06:20:11.910319 31283 maintenance_manager.cc:643] P 622c0f8959b74788a3a505b6acc75b6e: FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83) complete. Timing: real 0.010s	user 0.005s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3714,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:11.910790 31362 maintenance_manager.cc:419] P 622c0f8959b74788a3a505b6acc75b6e: Scheduling MajorDeltaCompactionOp(498b8d40c02e4483b6617319b8208f83): perf score=1.000000
I20260812 06:20:12.137176 31283 maintenance_manager.cc:643] P 622c0f8959b74788a3a505b6acc75b6e: MajorDeltaCompactionOp(498b8d40c02e4483b6617319b8208f83) complete. Timing: real 0.226s	user 0.140s	sys 0.076s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877207,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":996,"lbm_read_time_us":15072,"lbm_reads_lt_1ms":673,"lbm_write_time_us":36193,"lbm_writes_lt_1ms":643,"mutex_wait_us":446,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":9728,"update_count":3000}
I20260812 06:20:12.137991 31362 maintenance_manager.cc:419] P 622c0f8959b74788a3a505b6acc75b6e: Scheduling FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83): perf score=18.063937
I20260812 06:20:12.208506 31283 maintenance_manager.cc:643] P 622c0f8959b74788a3a505b6acc75b6e: FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83) complete. Timing: real 0.070s	user 0.037s	sys 0.024s Metrics: {"bytes_written":20512319,"delete_count":0,"lbm_write_time_us":27756,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:20:12.209019 31362 maintenance_manager.cc:419] P 622c0f8959b74788a3a505b6acc75b6e: Scheduling FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83): perf score=2.188937
I20260812 06:20:12.220618 31283 maintenance_manager.cc:643] P 622c0f8959b74788a3a505b6acc75b6e: FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83) complete. Timing: real 0.011s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4153,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:12.221082 31362 maintenance_manager.cc:419] P 622c0f8959b74788a3a505b6acc75b6e: Scheduling MajorDeltaCompactionOp(498b8d40c02e4483b6617319b8208f83): perf score=1.000000
I20260812 06:20:12.428314 31283 maintenance_manager.cc:643] P 622c0f8959b74788a3a505b6acc75b6e: MajorDeltaCompactionOp(498b8d40c02e4483b6617319b8208f83) complete. Timing: real 0.207s	user 0.137s	sys 0.068s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877106,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":852,"lbm_read_time_us":15884,"lbm_reads_lt_1ms":672,"lbm_write_time_us":33234,"lbm_writes_lt_1ms":643,"mutex_wait_us":389,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":80128,"update_count":3000}
I20260812 06:20:12.429075 31362 maintenance_manager.cc:419] P 622c0f8959b74788a3a505b6acc75b6e: Scheduling FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83): perf score=16.079562
I20260812 06:20:12.478415 31283 maintenance_manager.cc:643] P 622c0f8959b74788a3a505b6acc75b6e: FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83) complete. Timing: real 0.049s	user 0.037s	sys 0.008s Metrics: {"bytes_written":17845754,"delete_count":0,"lbm_write_time_us":21454,"lbm_writes_lt_1ms":438,"reinsert_count":0,"update_count":2175}
I20260812 06:20:12.478976 31362 maintenance_manager.cc:419] P 622c0f8959b74788a3a505b6acc75b6e: Scheduling FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83): perf score=1.196750
I20260812 06:20:12.500322 31283 maintenance_manager.cc:643] P 622c0f8959b74788a3a505b6acc75b6e: FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83) complete. Timing: real 0.021s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3077034,"delete_count":0,"lbm_write_time_us":3985,"lbm_writes_lt_1ms":78,"reinsert_count":0,"update_count":375}
I20260812 06:20:12.500844 31362 maintenance_manager.cc:419] P 622c0f8959b74788a3a505b6acc75b6e: Scheduling FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83): perf score=2.188937
I20260812 06:20:12.510568 31283 maintenance_manager.cc:643] P 622c0f8959b74788a3a505b6acc75b6e: FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83) complete. Timing: real 0.010s	user 0.004s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3702,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:12.511109 31362 maintenance_manager.cc:419] P 622c0f8959b74788a3a505b6acc75b6e: Scheduling FlushMRSOp(498b8d40c02e4483b6617319b8208f83): perf score=1.000000
I20260812 06:20:12.545725 31283 maintenance_manager.cc:643] P 622c0f8959b74788a3a505b6acc75b6e: FlushMRSOp(498b8d40c02e4483b6617319b8208f83) complete. Timing: real 0.034s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":81,"dirs.run_cpu_time_us":201,"dirs.run_wall_time_us":1604,"drs_written":1,"lbm_read_time_us":67,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2202,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:20:12.546411 31362 maintenance_manager.cc:419] P 622c0f8959b74788a3a505b6acc75b6e: Scheduling LogGCOp(498b8d40c02e4483b6617319b8208f83): free 128867663 bytes of WAL
I20260812 06:20:12.546651 31283 log_reader.cc:385] T 498b8d40c02e4483b6617319b8208f83: removed 13 log segments from log reader
I20260812 06:20:12.546696 31283 log.cc:1079] T 498b8d40c02e4483b6617319b8208f83 P 622c0f8959b74788a3a505b6acc75b6e: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/498b8d40c02e4483b6617319b8208f83/wal-000000027 (ops 128-132)
I20260812 06:20:12.546725 31283 log.cc:1079] T 498b8d40c02e4483b6617319b8208f83 P 622c0f8959b74788a3a505b6acc75b6e: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/498b8d40c02e4483b6617319b8208f83/wal-000000028 (ops 133-136)
I20260812 06:20:12.546792 31283 log.cc:1079] T 498b8d40c02e4483b6617319b8208f83 P 622c0f8959b74788a3a505b6acc75b6e: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/498b8d40c02e4483b6617319b8208f83/wal-000000029 (ops 137-141)
I20260812 06:20:12.546836 31283 log.cc:1079] T 498b8d40c02e4483b6617319b8208f83 P 622c0f8959b74788a3a505b6acc75b6e: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/498b8d40c02e4483b6617319b8208f83/wal-000000030 (ops 142-146)
I20260812 06:20:12.546882 31283 log.cc:1079] T 498b8d40c02e4483b6617319b8208f83 P 622c0f8959b74788a3a505b6acc75b6e: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/498b8d40c02e4483b6617319b8208f83/wal-000000031 (ops 147-151)
I20260812 06:20:12.546947 31283 log.cc:1079] T 498b8d40c02e4483b6617319b8208f83 P 622c0f8959b74788a3a505b6acc75b6e: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/498b8d40c02e4483b6617319b8208f83/wal-000000032 (ops 152-156)
I20260812 06:20:12.546984 31283 log.cc:1079] T 498b8d40c02e4483b6617319b8208f83 P 622c0f8959b74788a3a505b6acc75b6e: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/498b8d40c02e4483b6617319b8208f83/wal-000000033 (ops 157-160)
I20260812 06:20:12.547025 31283 log.cc:1079] T 498b8d40c02e4483b6617319b8208f83 P 622c0f8959b74788a3a505b6acc75b6e: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/498b8d40c02e4483b6617319b8208f83/wal-000000034 (ops 161-165)
I20260812 06:20:12.547065 31283 log.cc:1079] T 498b8d40c02e4483b6617319b8208f83 P 622c0f8959b74788a3a505b6acc75b6e: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/498b8d40c02e4483b6617319b8208f83/wal-000000035 (ops 166-170)
I20260812 06:20:12.547106 31283 log.cc:1079] T 498b8d40c02e4483b6617319b8208f83 P 622c0f8959b74788a3a505b6acc75b6e: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/498b8d40c02e4483b6617319b8208f83/wal-000000036 (ops 171-175)
I20260812 06:20:12.547147 31283 log.cc:1079] T 498b8d40c02e4483b6617319b8208f83 P 622c0f8959b74788a3a505b6acc75b6e: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/498b8d40c02e4483b6617319b8208f83/wal-000000037 (ops 176-180)
I20260812 06:20:12.547187 31283 log.cc:1079] T 498b8d40c02e4483b6617319b8208f83 P 622c0f8959b74788a3a505b6acc75b6e: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/498b8d40c02e4483b6617319b8208f83/wal-000000038 (ops 181-184)
I20260812 06:20:12.547226 31283 log.cc:1079] T 498b8d40c02e4483b6617319b8208f83 P 622c0f8959b74788a3a505b6acc75b6e: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/498b8d40c02e4483b6617319b8208f83/wal-000000039 (ops 185-189)
I20260812 06:20:12.574313 31283 maintenance_manager.cc:643] P 622c0f8959b74788a3a505b6acc75b6e: LogGCOp(498b8d40c02e4483b6617319b8208f83) complete. Timing: real 0.028s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:20:12.574992 31362 maintenance_manager.cc:419] P 622c0f8959b74788a3a505b6acc75b6e: Scheduling FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83): perf score=2.188937
I20260812 06:20:12.595938 31283 maintenance_manager.cc:643] P 622c0f8959b74788a3a505b6acc75b6e: FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83) complete. Timing: real 0.021s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4184708,"delete_count":0,"lbm_write_time_us":6679,"lbm_writes_lt_1ms":105,"reinsert_count":0,"update_count":510}
I20260812 06:20:12.596459 31362 maintenance_manager.cc:419] P 622c0f8959b74788a3a505b6acc75b6e: Scheduling LogGCOp(498b8d40c02e4483b6617319b8208f83): free 12018013 bytes of WAL
I20260812 06:20:12.596679 31283 log_reader.cc:385] T 498b8d40c02e4483b6617319b8208f83: removed 1 log segments from log reader
I20260812 06:20:12.596722 31283 log.cc:1079] T 498b8d40c02e4483b6617319b8208f83 P 622c0f8959b74788a3a505b6acc75b6e: Deleting log segment in path: /tmp/dist-test-taskNeBUCu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601908337-30933-0/minicluster-data/ts-0-root/wals/498b8d40c02e4483b6617319b8208f83/wal-000000040 (ops 190-194)
I20260812 06:20:12.599272 31283 maintenance_manager.cc:643] P 622c0f8959b74788a3a505b6acc75b6e: LogGCOp(498b8d40c02e4483b6617319b8208f83) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:20:12.599609 31362 maintenance_manager.cc:419] P 622c0f8959b74788a3a505b6acc75b6e: Scheduling UndoDeltaBlockGCOp(498b8d40c02e4483b6617319b8208f83): 493 bytes on disk
I20260812 06:20:12.600041 31283 maintenance_manager.cc:643] P 622c0f8959b74788a3a505b6acc75b6e: UndoDeltaBlockGCOp(498b8d40c02e4483b6617319b8208f83) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4}
I20260812 06:20:12.600615 31362 maintenance_manager.cc:419] P 622c0f8959b74788a3a505b6acc75b6e: Scheduling FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83): perf score=2.188937
I20260812 06:20:12.612316 31283 maintenance_manager.cc:643] P 622c0f8959b74788a3a505b6acc75b6e: FlushDeltaMemStoresOp(498b8d40c02e4483b6617319b8208f83) complete. Timing: real 0.012s	user 0.004s	sys 0.007s Metrics: {"bytes_written":4020608,"delete_count":0,"lbm_write_time_us":4557,"lbm_writes_lt_1ms":101,"reinsert_count":0,"update_count":490}
I20260812 06:20:12.612856 31362 maintenance_manager.cc:419] P 622c0f8959b74788a3a505b6acc75b6e: Scheduling MajorDeltaCompactionOp(498b8d40c02e4483b6617319b8208f83): perf score=1.000000
I20260812 06:20:12.724635 30933 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.961s	user 1.822s	sys 0.157s
I20260812 06:20:12.833637 30933 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.109s	user 0.001s	sys 0.000s
I20260812 06:20:12.834167 30933 tablet_server.cc:179] TabletServer@127.30.53.65:0 shutting down...
I20260812 06:20:12.842093 31283 maintenance_manager.cc:643] P 622c0f8959b74788a3a505b6acc75b6e: MajorDeltaCompactionOp(498b8d40c02e4483b6617319b8208f83) complete. Timing: real 0.229s	user 0.143s	sys 0.084s Metrics: {"cfile_cache_miss":835,"cfile_cache_miss_bytes":37082253,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":295,"lbm_read_time_us":17829,"lbm_reads_lt_1ms":871,"lbm_write_time_us":39182,"lbm_writes_lt_1ms":843,"mutex_wait_us":27,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":4992,"thread_start_us":72,"threads_started":1,"update_count":4000}
I20260812 06:20:12.843019 30933 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:20:12.843417 30933 tablet_replica.cc:333] T 498b8d40c02e4483b6617319b8208f83 P 622c0f8959b74788a3a505b6acc75b6e: stopping tablet replica
I20260812 06:20:12.843626 30933 raft_consensus.cc:2243] T 498b8d40c02e4483b6617319b8208f83 P 622c0f8959b74788a3a505b6acc75b6e [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:12.843837 30933 raft_consensus.cc:2272] T 498b8d40c02e4483b6617319b8208f83 P 622c0f8959b74788a3a505b6acc75b6e [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:12.852470 30933 tablet_server.cc:196] TabletServer@127.30.53.65:0 shutdown complete.
I20260812 06:20:12.912544 30933 master.cc:562] Master@127.30.53.126:37911 shutting down...
I20260812 06:20:12.916278 30933 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 775b00631c9e4f769ade064118ed4c62 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:12.916499 30933 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 775b00631c9e4f769ade064118ed4c62 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:12.916595 30933 tablet_replica.cc:333] T 00000000000000000000000000000000 P 775b00631c9e4f769ade064118ed4c62: stopping tablet replica
I20260812 06:20:12.929085 30933 master.cc:584] Master@127.30.53.126:37911 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5505 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11101 ms total)

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