[==========] 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:17:52.013437 16964 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.16.145.62:46565
I20260812 06:17:52.014569 16964 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:17:52.015233 16964 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:52.022553 16973 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:17:52.022562 16975 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:52.022845 16972 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:17:52.022811 16964 server_base.cc:1061] running on GCE node
I20260812 06:17:52.023411 16964 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:52.023506 16964 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:17:52.023631 16964 hybrid_clock.cc:648] HybridClock initialized: now 1786515472023629 us; error 0 us; skew 500 ppm
I20260812 06:17:52.025532 16964 webserver.cc:533] Webserver started at http://127.16.145.62:35261/ using document root <none> and password file <none>
I20260812 06:17:52.026075 16964 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:52.026129 16964 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:52.026317 16964 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:52.028023 16964 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515472001912-16964-0/minicluster-data/master-0-root/instance:
uuid: "bf7b47188fe74cce95682c975a1408d7"
format_stamp: "Formatted at 2026-08-12 06:17:52 on dist-test-slave-sb2z"
I20260812 06:17:52.031584 16964 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.004s	sys 0.000s
I20260812 06:17:52.033766 16983 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:17:52.034787 16964 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:52.034889 16964 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515472001912-16964-0/minicluster-data/master-0-root
uuid: "bf7b47188fe74cce95682c975a1408d7"
format_stamp: "Formatted at 2026-08-12 06:17:52 on dist-test-slave-sb2z"
I20260812 06:17:52.034978 16964 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515472001912-16964-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515472001912-16964-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515472001912-16964-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:17:52.047272 16964 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:52.048009 16964 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:17:52.048154 16964 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:52.056247 16964 rpc_server.cc:307] RPC server started. Bound to: 127.16.145.62:46565
I20260812 06:17:52.056257 17068 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.16.145.62:46565 every 8 connection(s)
I20260812 06:17:52.058641 17069 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:17:52.064565 17069 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P bf7b47188fe74cce95682c975a1408d7: Bootstrap starting.
I20260812 06:17:52.067051 17069 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P bf7b47188fe74cce95682c975a1408d7: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:52.068020 17069 log.cc:826] T 00000000000000000000000000000000 P bf7b47188fe74cce95682c975a1408d7: Log is configured to *not* fsync() on all Append() calls
I20260812 06:17:52.069811 17069 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P bf7b47188fe74cce95682c975a1408d7: No bootstrap required, opened a new log
I20260812 06:17:52.072736 17069 raft_consensus.cc:359] T 00000000000000000000000000000000 P bf7b47188fe74cce95682c975a1408d7 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bf7b47188fe74cce95682c975a1408d7" member_type: VOTER }
I20260812 06:17:52.072911 17069 raft_consensus.cc:385] T 00000000000000000000000000000000 P bf7b47188fe74cce95682c975a1408d7 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:52.073017 17069 raft_consensus.cc:740] T 00000000000000000000000000000000 P bf7b47188fe74cce95682c975a1408d7 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: bf7b47188fe74cce95682c975a1408d7, State: Initialized, Role: FOLLOWER
I20260812 06:17:52.073657 17069 consensus_queue.cc:260] T 00000000000000000000000000000000 P bf7b47188fe74cce95682c975a1408d7 [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: "bf7b47188fe74cce95682c975a1408d7" member_type: VOTER }
I20260812 06:17:52.073829 17069 raft_consensus.cc:399] T 00000000000000000000000000000000 P bf7b47188fe74cce95682c975a1408d7 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:52.073906 17069 raft_consensus.cc:493] T 00000000000000000000000000000000 P bf7b47188fe74cce95682c975a1408d7 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:52.074080 17069 raft_consensus.cc:3060] T 00000000000000000000000000000000 P bf7b47188fe74cce95682c975a1408d7 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:52.074939 17069 raft_consensus.cc:515] T 00000000000000000000000000000000 P bf7b47188fe74cce95682c975a1408d7 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bf7b47188fe74cce95682c975a1408d7" member_type: VOTER }
I20260812 06:17:52.075415 17069 leader_election.cc:304] T 00000000000000000000000000000000 P bf7b47188fe74cce95682c975a1408d7 [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: bf7b47188fe74cce95682c975a1408d7; no voters: 
I20260812 06:17:52.075799 17069 leader_election.cc:290] T 00000000000000000000000000000000 P bf7b47188fe74cce95682c975a1408d7 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:52.075917 17072 raft_consensus.cc:2804] T 00000000000000000000000000000000 P bf7b47188fe74cce95682c975a1408d7 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:52.076228 17072 raft_consensus.cc:697] T 00000000000000000000000000000000 P bf7b47188fe74cce95682c975a1408d7 [term 1 LEADER]: Becoming Leader. State: Replica: bf7b47188fe74cce95682c975a1408d7, State: Running, Role: LEADER
I20260812 06:17:52.076658 17072 consensus_queue.cc:237] T 00000000000000000000000000000000 P bf7b47188fe74cce95682c975a1408d7 [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: "bf7b47188fe74cce95682c975a1408d7" member_type: VOTER }
I20260812 06:17:52.076908 17069 sys_catalog.cc:565] T 00000000000000000000000000000000 P bf7b47188fe74cce95682c975a1408d7 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:52.078730 17076 sys_catalog.cc:455] T 00000000000000000000000000000000 P bf7b47188fe74cce95682c975a1408d7 [sys.catalog]: SysCatalogTable state changed. Reason: New leader bf7b47188fe74cce95682c975a1408d7. Latest consensus state: current_term: 1 leader_uuid: "bf7b47188fe74cce95682c975a1408d7" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bf7b47188fe74cce95682c975a1408d7" member_type: VOTER } }
I20260812 06:17:52.078881 17076 sys_catalog.cc:458] T 00000000000000000000000000000000 P bf7b47188fe74cce95682c975a1408d7 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:52.078758 17073 sys_catalog.cc:455] T 00000000000000000000000000000000 P bf7b47188fe74cce95682c975a1408d7 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "bf7b47188fe74cce95682c975a1408d7" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bf7b47188fe74cce95682c975a1408d7" member_type: VOTER } }
I20260812 06:17:52.079011 17073 sys_catalog.cc:458] T 00000000000000000000000000000000 P bf7b47188fe74cce95682c975a1408d7 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:52.079286 17086 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:52.082103 17086 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:52.082391 16964 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:52.087447 17086 catalog_manager.cc:1383] Generated new cluster ID: 7501def7dd684871ad1f87637c7c6ebc
I20260812 06:17:52.087549 17086 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:52.111299 17086 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:52.112637 17086 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:52.128181 17086 catalog_manager.cc:6092] T 00000000000000000000000000000000 P bf7b47188fe74cce95682c975a1408d7: Generated new TSK 0
I20260812 06:17:52.128911 17086 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:52.147305 16964 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:52.150236 17103 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:17:52.150247 17105 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:17:52.150408 16964 server_base.cc:1061] running on GCE node
W20260812 06:17:52.150247 17102 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:17:52.150734 16964 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:52.150784 16964 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:17:52.150800 16964 hybrid_clock.cc:648] HybridClock initialized: now 1786515472150801 us; error 0 us; skew 500 ppm
I20260812 06:17:52.151885 16964 webserver.cc:533] Webserver started at http://127.16.145.1:35833/ using document root <none> and password file <none>
I20260812 06:17:52.152081 16964 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:52.152133 16964 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:52.152243 16964 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:52.152665 16964 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515472001912-16964-0/minicluster-data/ts-0-root/instance:
uuid: "9f6fe0f6c37644fab4a5f1925e83542a"
format_stamp: "Formatted at 2026-08-12 06:17:52 on dist-test-slave-sb2z"
I20260812 06:17:52.154333 16964 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:52.155449 17111 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:17:52.155805 16964 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:52.155898 16964 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515472001912-16964-0/minicluster-data/ts-0-root
uuid: "9f6fe0f6c37644fab4a5f1925e83542a"
format_stamp: "Formatted at 2026-08-12 06:17:52 on dist-test-slave-sb2z"
I20260812 06:17:52.155980 16964 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515472001912-16964-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515472001912-16964-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515472001912-16964-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:17:52.165431 16964 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:52.166035 16964 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:52.166659 16964 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:52.167752 16964 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:52.167822 16964 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:52.167882 16964 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:52.167914 16964 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:52.174904 16964 rpc_server.cc:307] RPC server started. Bound to: 127.16.145.1:40805
I20260812 06:17:52.174993 17199 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.16.145.1:40805 every 8 connection(s)
I20260812 06:17:52.186124 17201 heartbeater.cc:344] Connected to a master server at 127.16.145.62:46565
I20260812 06:17:52.186422 17201 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:52.186889 17201 heartbeater.cc:507] Master 127.16.145.62:46565 requested a full tablet report, sending...
I20260812 06:17:52.188400 17011 ts_manager.cc:194] Registered new tserver with Master: 9f6fe0f6c37644fab4a5f1925e83542a (127.16.145.1:40805)
I20260812 06:17:52.189240 16964 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.013543134s
I20260812 06:17:52.189649 17011 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:40582
I20260812 06:17:52.199591 17011 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:40598:
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:17:52.214468 17151 tablet_service.cc:1511] Processing CreateTablet for tablet 3f2498ebdef34597993c06d5fd6b8ebf (DEFAULT_TABLE table=heavy-update-compaction-test [id=e5ae5763c5d149c29fe54f46ba48af24]), partition=
I20260812 06:17:52.215001 17151 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 3f2498ebdef34597993c06d5fd6b8ebf. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:52.218144 17229 tablet_bootstrap.cc:492] T 3f2498ebdef34597993c06d5fd6b8ebf P 9f6fe0f6c37644fab4a5f1925e83542a: Bootstrap starting.
I20260812 06:17:52.219192 17229 tablet_bootstrap.cc:654] T 3f2498ebdef34597993c06d5fd6b8ebf P 9f6fe0f6c37644fab4a5f1925e83542a: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:52.220424 17229 tablet_bootstrap.cc:492] T 3f2498ebdef34597993c06d5fd6b8ebf P 9f6fe0f6c37644fab4a5f1925e83542a: No bootstrap required, opened a new log
I20260812 06:17:52.220557 17229 ts_tablet_manager.cc:1403] T 3f2498ebdef34597993c06d5fd6b8ebf P 9f6fe0f6c37644fab4a5f1925e83542a: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:17:52.221026 17229 raft_consensus.cc:359] T 3f2498ebdef34597993c06d5fd6b8ebf P 9f6fe0f6c37644fab4a5f1925e83542a [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9f6fe0f6c37644fab4a5f1925e83542a" member_type: VOTER last_known_addr { host: "127.16.145.1" port: 40805 } }
I20260812 06:17:52.221155 17229 raft_consensus.cc:385] T 3f2498ebdef34597993c06d5fd6b8ebf P 9f6fe0f6c37644fab4a5f1925e83542a [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:52.221225 17229 raft_consensus.cc:740] T 3f2498ebdef34597993c06d5fd6b8ebf P 9f6fe0f6c37644fab4a5f1925e83542a [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 9f6fe0f6c37644fab4a5f1925e83542a, State: Initialized, Role: FOLLOWER
I20260812 06:17:52.221415 17229 consensus_queue.cc:260] T 3f2498ebdef34597993c06d5fd6b8ebf P 9f6fe0f6c37644fab4a5f1925e83542a [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: "9f6fe0f6c37644fab4a5f1925e83542a" member_type: VOTER last_known_addr { host: "127.16.145.1" port: 40805 } }
I20260812 06:17:52.221563 17229 raft_consensus.cc:399] T 3f2498ebdef34597993c06d5fd6b8ebf P 9f6fe0f6c37644fab4a5f1925e83542a [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:52.221616 17229 raft_consensus.cc:493] T 3f2498ebdef34597993c06d5fd6b8ebf P 9f6fe0f6c37644fab4a5f1925e83542a [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:52.221671 17229 raft_consensus.cc:3060] T 3f2498ebdef34597993c06d5fd6b8ebf P 9f6fe0f6c37644fab4a5f1925e83542a [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:52.222657 17229 raft_consensus.cc:515] T 3f2498ebdef34597993c06d5fd6b8ebf P 9f6fe0f6c37644fab4a5f1925e83542a [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9f6fe0f6c37644fab4a5f1925e83542a" member_type: VOTER last_known_addr { host: "127.16.145.1" port: 40805 } }
I20260812 06:17:52.222826 17229 leader_election.cc:304] T 3f2498ebdef34597993c06d5fd6b8ebf P 9f6fe0f6c37644fab4a5f1925e83542a [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: 9f6fe0f6c37644fab4a5f1925e83542a; no voters: 
I20260812 06:17:52.223078 17229 leader_election.cc:290] T 3f2498ebdef34597993c06d5fd6b8ebf P 9f6fe0f6c37644fab4a5f1925e83542a [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:52.223186 17232 raft_consensus.cc:2804] T 3f2498ebdef34597993c06d5fd6b8ebf P 9f6fe0f6c37644fab4a5f1925e83542a [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:52.223389 17232 raft_consensus.cc:697] T 3f2498ebdef34597993c06d5fd6b8ebf P 9f6fe0f6c37644fab4a5f1925e83542a [term 1 LEADER]: Becoming Leader. State: Replica: 9f6fe0f6c37644fab4a5f1925e83542a, State: Running, Role: LEADER
I20260812 06:17:52.223460 17229 ts_tablet_manager.cc:1434] T 3f2498ebdef34597993c06d5fd6b8ebf P 9f6fe0f6c37644fab4a5f1925e83542a: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:17:52.223774 17201 heartbeater.cc:499] Master 127.16.145.62:46565 was elected leader, sending a full tablet report...
I20260812 06:17:52.223727 17232 consensus_queue.cc:237] T 3f2498ebdef34597993c06d5fd6b8ebf P 9f6fe0f6c37644fab4a5f1925e83542a [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: "9f6fe0f6c37644fab4a5f1925e83542a" member_type: VOTER last_known_addr { host: "127.16.145.1" port: 40805 } }
I20260812 06:17:52.227193 17011 catalog_manager.cc:5719] T 3f2498ebdef34597993c06d5fd6b8ebf P 9f6fe0f6c37644fab4a5f1925e83542a reported cstate change: term changed from 0 to 1, leader changed from <none> to 9f6fe0f6c37644fab4a5f1925e83542a (127.16.145.1). New cstate: current_term: 1 leader_uuid: "9f6fe0f6c37644fab4a5f1925e83542a" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9f6fe0f6c37644fab4a5f1925e83542a" member_type: VOTER last_known_addr { host: "127.16.145.1" port: 40805 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:52.294647 16964 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.059s	user 0.014s	sys 0.012s
I20260812 06:17:52.426447 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling FlushMRSOp(3f2498ebdef34597993c06d5fd6b8ebf): perf score=15.086190
I20260812 06:17:52.599110 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: FlushMRSOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.172s	user 0.146s	sys 0.020s Metrics: {"bytes_written":11897250,"cfile_init":1,"compiler_manager_pool.queue_time_us":298,"delete_count":0,"dirs.queue_time_us":73,"dirs.run_cpu_time_us":250,"dirs.run_wall_time_us":1134,"drs_written":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4,"lbm_write_time_us":41338,"lbm_writes_lt_1ms":657,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":166,"threads_started":1,"update_count":1450}
I20260812 06:17:52.600508 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling LogGCOp(3f2498ebdef34597993c06d5fd6b8ebf): free 20743880 bytes of WAL
I20260812 06:17:52.600854 17119 log_reader.cc:385] T 3f2498ebdef34597993c06d5fd6b8ebf: removed 2 log segments from log reader
I20260812 06:17:52.600936 17119 log.cc:1079] T 3f2498ebdef34597993c06d5fd6b8ebf P 9f6fe0f6c37644fab4a5f1925e83542a: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/3f2498ebdef34597993c06d5fd6b8ebf/wal-000000001 (ops 1-6)
I20260812 06:17:52.601045 17119 log.cc:1079] T 3f2498ebdef34597993c06d5fd6b8ebf P 9f6fe0f6c37644fab4a5f1925e83542a: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/3f2498ebdef34597993c06d5fd6b8ebf/wal-000000002 (ops 7-11)
I20260812 06:17:52.606827 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: LogGCOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.006s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:17:52.607316 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf): perf score=2.188937
I20260812 06:17:52.621531 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5488,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:52.622008 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling UndoDeltaBlockGCOp(3f2498ebdef34597993c06d5fd6b8ebf): 12719217 bytes on disk
I20260812 06:17:52.622619 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: UndoDeltaBlockGCOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4}
I20260812 06:17:52.623040 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling MajorDeltaCompactionOp(3f2498ebdef34597993c06d5fd6b8ebf): perf score=1.000000
I20260812 06:17:52.757886 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: MajorDeltaCompactionOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.135s	user 0.103s	sys 0.031s Metrics: {"cfile_cache_miss":422,"cfile_cache_miss_bytes":20262037,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":550,"lbm_read_time_us":8813,"lbm_reads_lt_1ms":450,"lbm_write_time_us":25576,"lbm_writes_lt_1ms":433,"peak_mem_usage":49238594,"reinsert_count":0,"spinlock_wait_cycles":2560,"thread_start_us":347,"threads_started":5,"update_count":1950}
I20260812 06:17:52.758493 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf): perf score=11.118625
I20260812 06:17:52.792752 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.034s	user 0.021s	sys 0.012s Metrics: {"bytes_written":12676711,"delete_count":0,"lbm_write_time_us":15023,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1545}
I20260812 06:17:52.793407 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf): perf score=2.188937
I20260812 06:17:52.808992 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.015s	user 0.010s	sys 0.004s Metrics: {"bytes_written":3733434,"delete_count":0,"lbm_write_time_us":5804,"lbm_writes_lt_1ms":94,"reinsert_count":0,"update_count":455}
I20260812 06:17:52.809513 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling MajorDeltaCompactionOp(3f2498ebdef34597993c06d5fd6b8ebf): perf score=1.000000
I20260812 06:17:52.947991 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: MajorDeltaCompactionOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.138s	user 0.114s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672273,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":366,"lbm_read_time_us":10273,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26410,"lbm_writes_lt_1ms":443,"mutex_wait_us":137,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":17792,"update_count":2000}
I20260812 06:17:52.948750 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf): perf score=10.126437
I20260812 06:17:52.996641 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.048s	user 0.038s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20297,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:52.997145 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf): perf score=2.188937
I20260812 06:17:53.008690 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4190,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:53.009353 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling MajorDeltaCompactionOp(3f2498ebdef34597993c06d5fd6b8ebf): perf score=1.000000
I20260812 06:17:53.148831 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: MajorDeltaCompactionOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.139s	user 0.119s	sys 0.020s 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":1317,"lbm_read_time_us":9779,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27800,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1152,"update_count":2000}
I20260812 06:17:53.149329 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf): perf score=10.126437
I20260812 06:17:53.209856 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.060s	user 0.024s	sys 0.031s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":22525,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:53.210515 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf): perf score=2.188937
I20260812 06:17:53.221872 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4417,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:53.222400 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling MajorDeltaCompactionOp(3f2498ebdef34597993c06d5fd6b8ebf): perf score=1.000000
I20260812 06:17:53.389588 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: MajorDeltaCompactionOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.167s	user 0.112s	sys 0.051s 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":1294,"lbm_read_time_us":11420,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28110,"lbm_writes_lt_1ms":443,"mutex_wait_us":325,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:53.390341 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf): perf score=10.126437
I20260812 06:17:53.438284 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.048s	user 0.019s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16500,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:53.438863 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf): perf score=2.188937
I20260812 06:17:53.450425 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4428,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:53.451174 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling MajorDeltaCompactionOp(3f2498ebdef34597993c06d5fd6b8ebf): perf score=1.000000
I20260812 06:17:53.577095 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: MajorDeltaCompactionOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.126s	user 0.096s	sys 0.027s 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":1375,"lbm_read_time_us":8954,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25170,"lbm_writes_lt_1ms":443,"mutex_wait_us":489,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12416,"update_count":2000}
I20260812 06:17:53.577814 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf): perf score=10.126437
I20260812 06:17:53.625531 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.048s	user 0.031s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17779,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:53.626032 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf): perf score=2.188937
I20260812 06:17:53.639420 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.013s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5132,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:53.641626 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling MajorDeltaCompactionOp(3f2498ebdef34597993c06d5fd6b8ebf): perf score=1.000000
I20260812 06:17:53.764511 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: MajorDeltaCompactionOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.123s	user 0.105s	sys 0.016s 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":961,"lbm_read_time_us":9022,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23638,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:53.765379 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf): perf score=10.126437
I20260812 06:17:53.814428 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.049s	user 0.018s	sys 0.027s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17767,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:53.815027 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf): perf score=2.188937
I20260812 06:17:53.827826 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.013s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5105,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:53.828352 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling MajorDeltaCompactionOp(3f2498ebdef34597993c06d5fd6b8ebf): perf score=1.000000
I20260812 06:17:53.992936 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: MajorDeltaCompactionOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.164s	user 0.104s	sys 0.052s 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":1286,"lbm_read_time_us":11468,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27075,"lbm_writes_lt_1ms":443,"mutex_wait_us":589,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":886144,"update_count":2000}
I20260812 06:17:53.993782 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf): perf score=10.126437
I20260812 06:17:54.042646 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.049s	user 0.027s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16815,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:54.043232 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf): perf score=2.188937
I20260812 06:17:54.055573 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.012s	user 0.005s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4606,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:54.056231 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling FlushMRSOp(3f2498ebdef34597993c06d5fd6b8ebf): perf score=1.000000
I20260812 06:17:54.086833 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: FlushMRSOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.030s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1275443,"cfile_init":1,"dirs.queue_time_us":55,"dirs.run_cpu_time_us":219,"dirs.run_wall_time_us":1407,"drs_written":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1775,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:54.087796 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling LogGCOp(3f2498ebdef34597993c06d5fd6b8ebf): free 120553331 bytes of WAL
I20260812 06:17:54.088057 17119 log_reader.cc:385] T 3f2498ebdef34597993c06d5fd6b8ebf: removed 12 log segments from log reader
I20260812 06:17:54.088173 17119 log.cc:1079] T 3f2498ebdef34597993c06d5fd6b8ebf P 9f6fe0f6c37644fab4a5f1925e83542a: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/3f2498ebdef34597993c06d5fd6b8ebf/wal-000000003 (ops 12-16)
I20260812 06:17:54.088255 17119 log.cc:1079] T 3f2498ebdef34597993c06d5fd6b8ebf P 9f6fe0f6c37644fab4a5f1925e83542a: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/3f2498ebdef34597993c06d5fd6b8ebf/wal-000000004 (ops 17-21)
I20260812 06:17:54.088315 17119 log.cc:1079] T 3f2498ebdef34597993c06d5fd6b8ebf P 9f6fe0f6c37644fab4a5f1925e83542a: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/3f2498ebdef34597993c06d5fd6b8ebf/wal-000000005 (ops 22-26)
I20260812 06:17:54.088356 17119 log.cc:1079] T 3f2498ebdef34597993c06d5fd6b8ebf P 9f6fe0f6c37644fab4a5f1925e83542a: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/3f2498ebdef34597993c06d5fd6b8ebf/wal-000000006 (ops 27-30)
I20260812 06:17:54.088394 17119 log.cc:1079] T 3f2498ebdef34597993c06d5fd6b8ebf P 9f6fe0f6c37644fab4a5f1925e83542a: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/3f2498ebdef34597993c06d5fd6b8ebf/wal-000000007 (ops 31-35)
I20260812 06:17:54.088431 17119 log.cc:1079] T 3f2498ebdef34597993c06d5fd6b8ebf P 9f6fe0f6c37644fab4a5f1925e83542a: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/3f2498ebdef34597993c06d5fd6b8ebf/wal-000000008 (ops 36-40)
I20260812 06:17:54.088469 17119 log.cc:1079] T 3f2498ebdef34597993c06d5fd6b8ebf P 9f6fe0f6c37644fab4a5f1925e83542a: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/3f2498ebdef34597993c06d5fd6b8ebf/wal-000000009 (ops 41-45)
I20260812 06:17:54.088505 17119 log.cc:1079] T 3f2498ebdef34597993c06d5fd6b8ebf P 9f6fe0f6c37644fab4a5f1925e83542a: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/3f2498ebdef34597993c06d5fd6b8ebf/wal-000000010 (ops 46-50)
I20260812 06:17:54.088542 17119 log.cc:1079] T 3f2498ebdef34597993c06d5fd6b8ebf P 9f6fe0f6c37644fab4a5f1925e83542a: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/3f2498ebdef34597993c06d5fd6b8ebf/wal-000000011 (ops 51-55)
I20260812 06:17:54.088574 17119 log.cc:1079] T 3f2498ebdef34597993c06d5fd6b8ebf P 9f6fe0f6c37644fab4a5f1925e83542a: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/3f2498ebdef34597993c06d5fd6b8ebf/wal-000000012 (ops 56-60)
I20260812 06:17:54.088601 17119 log.cc:1079] T 3f2498ebdef34597993c06d5fd6b8ebf P 9f6fe0f6c37644fab4a5f1925e83542a: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/3f2498ebdef34597993c06d5fd6b8ebf/wal-000000013 (ops 61-64)
I20260812 06:17:54.088644 17119 log.cc:1079] T 3f2498ebdef34597993c06d5fd6b8ebf P 9f6fe0f6c37644fab4a5f1925e83542a: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/3f2498ebdef34597993c06d5fd6b8ebf/wal-000000014 (ops 65-69)
I20260812 06:17:54.118491 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: LogGCOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.030s	user 0.000s	sys 0.028s Metrics: {}
I20260812 06:17:54.119050 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf): perf score=3.181125
I20260812 06:17:54.145238 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.026s	user 0.009s	sys 0.015s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":7289,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:54.145781 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling LogGCOp(3f2498ebdef34597993c06d5fd6b8ebf): free 12017983 bytes of WAL
I20260812 06:17:54.146015 17119 log_reader.cc:385] T 3f2498ebdef34597993c06d5fd6b8ebf: removed 1 log segments from log reader
I20260812 06:17:54.146093 17119 log.cc:1079] T 3f2498ebdef34597993c06d5fd6b8ebf P 9f6fe0f6c37644fab4a5f1925e83542a: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/3f2498ebdef34597993c06d5fd6b8ebf/wal-000000015 (ops 70-74)
I20260812 06:17:54.148763 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: LogGCOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.003s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:17:54.149135 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf): perf score=2.188937
I20260812 06:17:54.159759 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.010s	user 0.009s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3927,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:54.160207 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling UndoDeltaBlockGCOp(3f2498ebdef34597993c06d5fd6b8ebf): 483 bytes on disk
I20260812 06:17:54.160651 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: UndoDeltaBlockGCOp(3f2498ebdef34597993c06d5fd6b8ebf) 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:17:54.161127 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling MajorDeltaCompactionOp(3f2498ebdef34597993c06d5fd6b8ebf): perf score=1.000000
I20260812 06:17:54.367718 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: MajorDeltaCompactionOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.206s	user 0.139s	sys 0.059s 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":665,"lbm_read_time_us":14990,"lbm_reads_lt_1ms":674,"lbm_write_time_us":35428,"lbm_writes_lt_1ms":643,"mutex_wait_us":3,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":7680,"thread_start_us":82,"threads_started":1,"update_count":3000}
I20260812 06:17:54.368294 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf): perf score=14.095187
I20260812 06:17:54.430282 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.062s	user 0.028s	sys 0.027s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22082,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:17:54.430881 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf): perf score=2.188937
I20260812 06:17:54.442586 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4466,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:54.443298 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling MajorDeltaCompactionOp(3f2498ebdef34597993c06d5fd6b8ebf): perf score=1.000000
I20260812 06:17:54.632236 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: MajorDeltaCompactionOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.189s	user 0.131s	sys 0.052s 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":800,"lbm_read_time_us":14790,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28459,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6400,"update_count":2500}
I20260812 06:17:54.632969 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf): perf score=11.118625
I20260812 06:17:54.693080 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.060s	user 0.019s	sys 0.028s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":21712,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:54.693622 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf): perf score=6.157687
I20260812 06:17:54.722759 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.029s	user 0.011s	sys 0.015s Metrics: {"bytes_written":7794836,"delete_count":0,"lbm_write_time_us":8770,"lbm_writes_lt_1ms":193,"reinsert_count":0,"update_count":950}
I20260812 06:17:54.723461 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling MajorDeltaCompactionOp(3f2498ebdef34597993c06d5fd6b8ebf): perf score=1.000000
I20260812 06:17:54.909835 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: MajorDeltaCompactionOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.186s	user 0.123s	sys 0.061s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774694,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":296,"lbm_read_time_us":12560,"lbm_reads_lt_1ms":564,"lbm_write_time_us":34739,"lbm_writes_lt_1ms":543,"mutex_wait_us":1,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:17:54.910501 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf): perf score=14.095187
I20260812 06:17:54.968643 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.058s	user 0.037s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25853,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:17:54.969230 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf): perf score=2.188937
I20260812 06:17:54.984203 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.015s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5390,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:54.984712 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling MajorDeltaCompactionOp(3f2498ebdef34597993c06d5fd6b8ebf): perf score=1.000000
I20260812 06:17:55.183145 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: MajorDeltaCompactionOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.198s	user 0.115s	sys 0.077s 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":335,"lbm_read_time_us":10987,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31914,"lbm_writes_lt_1ms":543,"mutex_wait_us":86,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":16512,"update_count":2500}
I20260812 06:17:55.187273 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf): perf score=14.095187
I20260812 06:17:55.239871 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.052s	user 0.028s	sys 0.020s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":21498,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:55.240383 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf): perf score=2.188937
I20260812 06:17:55.252776 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4274,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:55.253518 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling MajorDeltaCompactionOp(3f2498ebdef34597993c06d5fd6b8ebf): perf score=1.000000
I20260812 06:17:55.427832 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: MajorDeltaCompactionOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.174s	user 0.119s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":505,"lbm_read_time_us":10392,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31110,"lbm_writes_lt_1ms":543,"mutex_wait_us":3,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":2500}
I20260812 06:17:55.428645 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf): perf score=14.095187
I20260812 06:17:55.481257 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.052s	user 0.034s	sys 0.012s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20819,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:55.481917 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf): perf score=2.188937
I20260812 06:17:55.494330 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4226,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:55.494926 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling MajorDeltaCompactionOp(3f2498ebdef34597993c06d5fd6b8ebf): perf score=1.000000
I20260812 06:17:55.657975 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: MajorDeltaCompactionOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.163s	user 0.105s	sys 0.047s 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":980,"lbm_read_time_us":9679,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32257,"lbm_writes_lt_1ms":543,"mutex_wait_us":299,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4352,"update_count":2500}
I20260812 06:17:55.658669 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf): perf score=14.095187
I20260812 06:17:55.710366 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.051s	user 0.026s	sys 0.021s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22556,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:55.711025 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf): perf score=2.188937
I20260812 06:17:55.725710 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5542,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:55.726243 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling FlushMRSOp(3f2498ebdef34597993c06d5fd6b8ebf): perf score=1.000000
I20260812 06:17:55.760557 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: FlushMRSOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.034s	user 0.029s	sys 0.004s Metrics: {"bytes_written":1357579,"cfile_init":1,"dirs.queue_time_us":146,"dirs.run_cpu_time_us":209,"dirs.run_wall_time_us":1403,"drs_written":1,"lbm_read_time_us":43,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1805,"lbm_writes_lt_1ms":44,"peak_mem_usage":0,"rows_written":33}
I20260812 06:17:55.761376 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling LogGCOp(3f2498ebdef34597993c06d5fd6b8ebf): free 121006454 bytes of WAL
I20260812 06:17:55.761648 17119 log_reader.cc:385] T 3f2498ebdef34597993c06d5fd6b8ebf: removed 12 log segments from log reader
I20260812 06:17:55.761698 17119 log.cc:1079] T 3f2498ebdef34597993c06d5fd6b8ebf P 9f6fe0f6c37644fab4a5f1925e83542a: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/3f2498ebdef34597993c06d5fd6b8ebf/wal-000000016 (ops 75-79)
I20260812 06:17:55.761729 17119 log.cc:1079] T 3f2498ebdef34597993c06d5fd6b8ebf P 9f6fe0f6c37644fab4a5f1925e83542a: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/3f2498ebdef34597993c06d5fd6b8ebf/wal-000000017 (ops 80-84)
I20260812 06:17:55.761747 17119 log.cc:1079] T 3f2498ebdef34597993c06d5fd6b8ebf P 9f6fe0f6c37644fab4a5f1925e83542a: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/3f2498ebdef34597993c06d5fd6b8ebf/wal-000000018 (ops 85-88)
I20260812 06:17:55.761813 17119 log.cc:1079] T 3f2498ebdef34597993c06d5fd6b8ebf P 9f6fe0f6c37644fab4a5f1925e83542a: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/3f2498ebdef34597993c06d5fd6b8ebf/wal-000000019 (ops 89-93)
I20260812 06:17:55.761878 17119 log.cc:1079] T 3f2498ebdef34597993c06d5fd6b8ebf P 9f6fe0f6c37644fab4a5f1925e83542a: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/3f2498ebdef34597993c06d5fd6b8ebf/wal-000000020 (ops 94-98)
I20260812 06:17:55.761922 17119 log.cc:1079] T 3f2498ebdef34597993c06d5fd6b8ebf P 9f6fe0f6c37644fab4a5f1925e83542a: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/3f2498ebdef34597993c06d5fd6b8ebf/wal-000000021 (ops 99-103)
I20260812 06:17:55.761981 17119 log.cc:1079] T 3f2498ebdef34597993c06d5fd6b8ebf P 9f6fe0f6c37644fab4a5f1925e83542a: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/3f2498ebdef34597993c06d5fd6b8ebf/wal-000000022 (ops 104-108)
I20260812 06:17:55.762022 17119 log.cc:1079] T 3f2498ebdef34597993c06d5fd6b8ebf P 9f6fe0f6c37644fab4a5f1925e83542a: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/3f2498ebdef34597993c06d5fd6b8ebf/wal-000000023 (ops 109-113)
I20260812 06:17:55.762063 17119 log.cc:1079] T 3f2498ebdef34597993c06d5fd6b8ebf P 9f6fe0f6c37644fab4a5f1925e83542a: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/3f2498ebdef34597993c06d5fd6b8ebf/wal-000000024 (ops 114-118)
I20260812 06:17:55.762105 17119 log.cc:1079] T 3f2498ebdef34597993c06d5fd6b8ebf P 9f6fe0f6c37644fab4a5f1925e83542a: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/3f2498ebdef34597993c06d5fd6b8ebf/wal-000000025 (ops 119-123)
I20260812 06:17:55.762143 17119 log.cc:1079] T 3f2498ebdef34597993c06d5fd6b8ebf P 9f6fe0f6c37644fab4a5f1925e83542a: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/3f2498ebdef34597993c06d5fd6b8ebf/wal-000000026 (ops 124-128)
I20260812 06:17:55.762185 17119 log.cc:1079] T 3f2498ebdef34597993c06d5fd6b8ebf P 9f6fe0f6c37644fab4a5f1925e83542a: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/3f2498ebdef34597993c06d5fd6b8ebf/wal-000000027 (ops 129-133)
I20260812 06:17:55.788972 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: LogGCOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.027s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:17:55.789556 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling UndoDeltaBlockGCOp(3f2498ebdef34597993c06d5fd6b8ebf): 508 bytes on disk
I20260812 06:17:55.790071 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: UndoDeltaBlockGCOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4}
I20260812 06:17:55.790704 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf): perf score=3.181125
I20260812 06:17:55.804811 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.014s	user 0.004s	sys 0.009s Metrics: {"bytes_written":5210311,"delete_count":0,"lbm_write_time_us":5597,"lbm_writes_lt_1ms":130,"reinsert_count":0,"update_count":635}
I20260812 06:17:55.805322 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling LogGCOp(3f2498ebdef34597993c06d5fd6b8ebf): free 8767145 bytes of WAL
I20260812 06:17:55.805557 17119 log_reader.cc:385] T 3f2498ebdef34597993c06d5fd6b8ebf: removed 1 log segments from log reader
I20260812 06:17:55.805611 17119 log.cc:1079] T 3f2498ebdef34597993c06d5fd6b8ebf P 9f6fe0f6c37644fab4a5f1925e83542a: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/3f2498ebdef34597993c06d5fd6b8ebf/wal-000000028 (ops 134-138)
I20260812 06:17:55.807451 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: LogGCOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:17:55.808077 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf): perf score=1.196750
I20260812 06:17:55.831698 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.023s	user 0.006s	sys 0.015s Metrics: {"bytes_written":2994980,"delete_count":0,"lbm_write_time_us":4368,"lbm_writes_lt_1ms":76,"reinsert_count":0,"update_count":365}
I20260812 06:17:55.832365 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling MajorDeltaCompactionOp(3f2498ebdef34597993c06d5fd6b8ebf): perf score=1.000000
I20260812 06:17:56.062819 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: MajorDeltaCompactionOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.230s	user 0.148s	sys 0.076s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979723,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1708,"lbm_read_time_us":16834,"lbm_reads_lt_1ms":766,"lbm_write_time_us":40180,"lbm_writes_lt_1ms":743,"mutex_wait_us":380,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":10496,"thread_start_us":104,"threads_started":1,"update_count":3500}
I20260812 06:17:56.063362 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf): perf score=18.063937
I20260812 06:17:56.127751 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.064s	user 0.033s	sys 0.030s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":30093,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":502,"reinsert_count":0,"update_count":2500}
I20260812 06:17:56.128326 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf): perf score=2.188937
I20260812 06:17:56.141434 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.013s	user 0.002s	sys 0.009s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4713,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:56.142246 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling MajorDeltaCompactionOp(3f2498ebdef34597993c06d5fd6b8ebf): perf score=1.000000
I20260812 06:17:56.329926 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: MajorDeltaCompactionOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.187s	user 0.123s	sys 0.064s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877101,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":994,"lbm_read_time_us":14862,"lbm_reads_lt_1ms":672,"lbm_write_time_us":31780,"lbm_writes_lt_1ms":643,"mutex_wait_us":25,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":81024,"update_count":3000}
I20260812 06:17:56.330437 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf): perf score=14.095187
I20260812 06:17:56.389266 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.059s	user 0.028s	sys 0.027s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":28609,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:17:56.389846 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf): perf score=2.188937
I20260812 06:17:56.402803 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.013s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4494,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:56.403508 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling MajorDeltaCompactionOp(3f2498ebdef34597993c06d5fd6b8ebf): perf score=1.000000
I20260812 06:17:56.587803 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: MajorDeltaCompactionOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.184s	user 0.114s	sys 0.068s 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":718,"lbm_read_time_us":12732,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31605,"lbm_writes_lt_1ms":543,"mutex_wait_us":16,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7936,"update_count":2500}
I20260812 06:17:56.588459 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf): perf score=14.095187
I20260812 06:17:56.652026 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.063s	user 0.026s	sys 0.027s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19761,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:56.652645 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf): perf score=2.188937
I20260812 06:17:56.663982 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4293,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:56.664531 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling MajorDeltaCompactionOp(3f2498ebdef34597993c06d5fd6b8ebf): perf score=1.000000
I20260812 06:17:56.863768 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: MajorDeltaCompactionOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.199s	user 0.128s	sys 0.069s 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":1585,"lbm_read_time_us":14016,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33616,"lbm_writes_lt_1ms":543,"mutex_wait_us":2,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2500}
I20260812 06:17:56.864717 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf): perf score=11.118625
I20260812 06:17:56.902208 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.034s	user 0.023s	sys 0.009s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":14736,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:56.903286 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf): perf score=2.188937
I20260812 06:17:56.936730 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.033s	user 0.008s	sys 0.006s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4783,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:56.937321 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf): perf score=2.188937
I20260812 06:17:56.948590 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4392,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:56.949141 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling MajorDeltaCompactionOp(3f2498ebdef34597993c06d5fd6b8ebf): perf score=1.000000
I20260812 06:17:57.122036 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: MajorDeltaCompactionOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.173s	user 0.128s	sys 0.044s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774800,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":560,"lbm_read_time_us":13925,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30190,"lbm_writes_lt_1ms":543,"mutex_wait_us":51,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":19200,"update_count":2500}
I20260812 06:17:57.122697 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf): perf score=11.118625
I20260812 06:17:57.162631 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.040s	user 0.029s	sys 0.007s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":16622,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:17:57.163516 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf): perf score=2.188937
I20260812 06:17:57.180317 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.017s	user 0.011s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4836,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:57.180838 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf): perf score=2.188937
I20260812 06:17:57.202116 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.021s	user 0.004s	sys 0.015s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4117,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:57.202733 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling MajorDeltaCompactionOp(3f2498ebdef34597993c06d5fd6b8ebf): perf score=1.000000
I20260812 06:17:57.385440 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: MajorDeltaCompactionOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.182s	user 0.114s	sys 0.067s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":999,"lbm_read_time_us":12721,"lbm_reads_lt_1ms":573,"lbm_write_time_us":31506,"lbm_writes_lt_1ms":543,"mutex_wait_us":29,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3584,"update_count":2500}
I20260812 06:17:57.386237 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf): perf score=10.126437
I20260812 06:17:57.422374 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.036s	user 0.017s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15709,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:57.423118 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf): perf score=2.188937
I20260812 06:17:57.438611 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.015s	user 0.009s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5327,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:57.439308 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling FlushMRSOp(3f2498ebdef34597993c06d5fd6b8ebf): perf score=1.000000
I20260812 06:17:57.465574 16964 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.171s	user 1.852s	sys 0.133s
I20260812 06:17:57.474761 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: FlushMRSOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.035s	user 0.029s	sys 0.004s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":75,"dirs.run_cpu_time_us":177,"dirs.run_wall_time_us":1344,"drs_written":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2054,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:57.475678 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling LogGCOp(3f2498ebdef34597993c06d5fd6b8ebf): free 124257457 bytes of WAL
I20260812 06:17:57.475948 17119 log_reader.cc:385] T 3f2498ebdef34597993c06d5fd6b8ebf: removed 12 log segments from log reader
I20260812 06:17:57.476019 17119 log.cc:1079] T 3f2498ebdef34597993c06d5fd6b8ebf P 9f6fe0f6c37644fab4a5f1925e83542a: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/3f2498ebdef34597993c06d5fd6b8ebf/wal-000000029 (ops 139-143)
I20260812 06:17:57.476075 17119 log.cc:1079] T 3f2498ebdef34597993c06d5fd6b8ebf P 9f6fe0f6c37644fab4a5f1925e83542a: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/3f2498ebdef34597993c06d5fd6b8ebf/wal-000000030 (ops 144-148)
I20260812 06:17:57.476135 17119 log.cc:1079] T 3f2498ebdef34597993c06d5fd6b8ebf P 9f6fe0f6c37644fab4a5f1925e83542a: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/3f2498ebdef34597993c06d5fd6b8ebf/wal-000000031 (ops 149-152)
I20260812 06:17:57.476177 17119 log.cc:1079] T 3f2498ebdef34597993c06d5fd6b8ebf P 9f6fe0f6c37644fab4a5f1925e83542a: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/3f2498ebdef34597993c06d5fd6b8ebf/wal-000000032 (ops 153-157)
I20260812 06:17:57.476212 17119 log.cc:1079] T 3f2498ebdef34597993c06d5fd6b8ebf P 9f6fe0f6c37644fab4a5f1925e83542a: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/3f2498ebdef34597993c06d5fd6b8ebf/wal-000000033 (ops 158-162)
I20260812 06:17:57.476248 17119 log.cc:1079] T 3f2498ebdef34597993c06d5fd6b8ebf P 9f6fe0f6c37644fab4a5f1925e83542a: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/3f2498ebdef34597993c06d5fd6b8ebf/wal-000000034 (ops 163-167)
I20260812 06:17:57.476282 17119 log.cc:1079] T 3f2498ebdef34597993c06d5fd6b8ebf P 9f6fe0f6c37644fab4a5f1925e83542a: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/3f2498ebdef34597993c06d5fd6b8ebf/wal-000000035 (ops 168-173)
I20260812 06:17:57.476320 17119 log.cc:1079] T 3f2498ebdef34597993c06d5fd6b8ebf P 9f6fe0f6c37644fab4a5f1925e83542a: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/3f2498ebdef34597993c06d5fd6b8ebf/wal-000000036 (ops 174-178)
I20260812 06:17:57.476356 17119 log.cc:1079] T 3f2498ebdef34597993c06d5fd6b8ebf P 9f6fe0f6c37644fab4a5f1925e83542a: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/3f2498ebdef34597993c06d5fd6b8ebf/wal-000000037 (ops 179-183)
I20260812 06:17:57.476392 17119 log.cc:1079] T 3f2498ebdef34597993c06d5fd6b8ebf P 9f6fe0f6c37644fab4a5f1925e83542a: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/3f2498ebdef34597993c06d5fd6b8ebf/wal-000000038 (ops 184-188)
I20260812 06:17:57.476430 17119 log.cc:1079] T 3f2498ebdef34597993c06d5fd6b8ebf P 9f6fe0f6c37644fab4a5f1925e83542a: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/3f2498ebdef34597993c06d5fd6b8ebf/wal-000000039 (ops 189-192)
I20260812 06:17:57.476467 17119 log.cc:1079] T 3f2498ebdef34597993c06d5fd6b8ebf P 9f6fe0f6c37644fab4a5f1925e83542a: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/3f2498ebdef34597993c06d5fd6b8ebf/wal-000000040 (ops 193-197)
I20260812 06:17:57.501787 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: LogGCOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.026s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:17:57.502301 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling UndoDeltaBlockGCOp(3f2498ebdef34597993c06d5fd6b8ebf): 482 bytes on disk
I20260812 06:17:57.502760 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: UndoDeltaBlockGCOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4}
I20260812 06:17:57.503360 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf): perf score=2.188937
I20260812 06:17:57.515796 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: FlushDeltaMemStoresOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.012s	user 0.005s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4315,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:57.516294 17205 maintenance_manager.cc:419] P 9f6fe0f6c37644fab4a5f1925e83542a: Scheduling MajorDeltaCompactionOp(3f2498ebdef34597993c06d5fd6b8ebf): perf score=1.000000
I20260812 06:17:57.518021 16964 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.052s	user 0.001s	sys 0.000s
I20260812 06:17:57.518635 16964 tablet_server.cc:179] TabletServer@127.16.145.1:0 shutting down...
I20260812 06:17:57.628823 17119 maintenance_manager.cc:643] P 9f6fe0f6c37644fab4a5f1925e83542a: MajorDeltaCompactionOp(3f2498ebdef34597993c06d5fd6b8ebf) complete. Timing: real 0.112s	user 0.075s	sys 0.036s Metrics: {"cfile_cache_hit":432,"cfile_cache_hit_bytes":20672277,"cfile_cache_miss":101,"cfile_cache_miss_bytes":4102531,"cfile_init":3,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":705,"lbm_read_time_us":1987,"lbm_reads_lt_1ms":113,"lbm_write_time_us":26092,"lbm_writes_lt_1ms":543,"mutex_wait_us":73,"peak_mem_usage":63115900,"reinsert_count":0,"thread_start_us":87,"threads_started":1,"update_count":2500}
I20260812 06:17:57.629884 16964 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:57.630312 16964 tablet_replica.cc:333] T 3f2498ebdef34597993c06d5fd6b8ebf P 9f6fe0f6c37644fab4a5f1925e83542a: stopping tablet replica
I20260812 06:17:57.630587 16964 raft_consensus.cc:2243] T 3f2498ebdef34597993c06d5fd6b8ebf P 9f6fe0f6c37644fab4a5f1925e83542a [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:57.630836 16964 raft_consensus.cc:2272] T 3f2498ebdef34597993c06d5fd6b8ebf P 9f6fe0f6c37644fab4a5f1925e83542a [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:57.646768 16964 tablet_server.cc:196] TabletServer@127.16.145.1:0 shutdown complete.
I20260812 06:17:57.673508 16964 master.cc:562] Master@127.16.145.62:46565 shutting down...
I20260812 06:17:57.678022 16964 raft_consensus.cc:2243] T 00000000000000000000000000000000 P bf7b47188fe74cce95682c975a1408d7 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:57.678277 16964 raft_consensus.cc:2272] T 00000000000000000000000000000000 P bf7b47188fe74cce95682c975a1408d7 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:57.678372 16964 tablet_replica.cc:333] T 00000000000000000000000000000000 P bf7b47188fe74cce95682c975a1408d7: stopping tablet replica
I20260812 06:17:57.691331 16964 master.cc:584] Master@127.16.145.62:46565 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5773 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:17:57.785913 16964 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.16.145.62:35513
I20260812 06:17:57.786376 16964 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:17:57.788825 16964 server_base.cc:1061] running on GCE node
W20260812 06:17:57.788986 17258 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:17:57.788910 17257 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:17:57.789129 17260 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:17:57.789391 16964 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:57.789439 16964 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:17:57.789455 16964 hybrid_clock.cc:648] HybridClock initialized: now 1786515477789456 us; error 0 us; skew 500 ppm
I20260812 06:17:57.790444 16964 webserver.cc:533] Webserver started at http://127.16.145.62:42041/ using document root <none> and password file <none>
I20260812 06:17:57.790664 16964 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:57.790727 16964 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:57.790815 16964 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:57.791291 16964 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515472001912-16964-0/minicluster-data/master-0-root/instance:
uuid: "d0125961fe0e410db2db5a2111417526"
format_stamp: "Formatted at 2026-08-12 06:17:57 on dist-test-slave-sb2z"
I20260812 06:17:57.793007 16964 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:57.794184 17268 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:17:57.794487 16964 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:57.794569 16964 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515472001912-16964-0/minicluster-data/master-0-root
uuid: "d0125961fe0e410db2db5a2111417526"
format_stamp: "Formatted at 2026-08-12 06:17:57 on dist-test-slave-sb2z"
I20260812 06:17:57.794641 16964 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515472001912-16964-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515472001912-16964-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515472001912-16964-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:17:57.804688 16964 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:57.805074 16964 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:57.809298 16964 rpc_server.cc:307] RPC server started. Bound to: 127.16.145.62:35513
I20260812 06:17:57.824860 17347 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.16.145.62:35513 every 8 connection(s)
I20260812 06:17:57.825554 17348 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:17:57.827677 17348 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P d0125961fe0e410db2db5a2111417526: Bootstrap starting.
I20260812 06:17:57.828547 17348 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P d0125961fe0e410db2db5a2111417526: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:57.829787 17348 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P d0125961fe0e410db2db5a2111417526: No bootstrap required, opened a new log
I20260812 06:17:57.830273 17348 raft_consensus.cc:359] T 00000000000000000000000000000000 P d0125961fe0e410db2db5a2111417526 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d0125961fe0e410db2db5a2111417526" member_type: VOTER }
I20260812 06:17:57.830399 17348 raft_consensus.cc:385] T 00000000000000000000000000000000 P d0125961fe0e410db2db5a2111417526 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:57.830452 17348 raft_consensus.cc:740] T 00000000000000000000000000000000 P d0125961fe0e410db2db5a2111417526 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: d0125961fe0e410db2db5a2111417526, State: Initialized, Role: FOLLOWER
I20260812 06:17:57.830669 17348 consensus_queue.cc:260] T 00000000000000000000000000000000 P d0125961fe0e410db2db5a2111417526 [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: "d0125961fe0e410db2db5a2111417526" member_type: VOTER }
I20260812 06:17:57.830775 17348 raft_consensus.cc:399] T 00000000000000000000000000000000 P d0125961fe0e410db2db5a2111417526 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:57.830823 17348 raft_consensus.cc:493] T 00000000000000000000000000000000 P d0125961fe0e410db2db5a2111417526 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:57.830881 17348 raft_consensus.cc:3060] T 00000000000000000000000000000000 P d0125961fe0e410db2db5a2111417526 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:57.831650 17348 raft_consensus.cc:515] T 00000000000000000000000000000000 P d0125961fe0e410db2db5a2111417526 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d0125961fe0e410db2db5a2111417526" member_type: VOTER }
I20260812 06:17:57.831808 17348 leader_election.cc:304] T 00000000000000000000000000000000 P d0125961fe0e410db2db5a2111417526 [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: d0125961fe0e410db2db5a2111417526; no voters: 
I20260812 06:17:57.832043 17348 leader_election.cc:290] T 00000000000000000000000000000000 P d0125961fe0e410db2db5a2111417526 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:57.832186 17354 raft_consensus.cc:2804] T 00000000000000000000000000000000 P d0125961fe0e410db2db5a2111417526 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:57.832459 17354 raft_consensus.cc:697] T 00000000000000000000000000000000 P d0125961fe0e410db2db5a2111417526 [term 1 LEADER]: Becoming Leader. State: Replica: d0125961fe0e410db2db5a2111417526, State: Running, Role: LEADER
I20260812 06:17:57.832574 17348 sys_catalog.cc:565] T 00000000000000000000000000000000 P d0125961fe0e410db2db5a2111417526 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:57.832620 17354 consensus_queue.cc:237] T 00000000000000000000000000000000 P d0125961fe0e410db2db5a2111417526 [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: "d0125961fe0e410db2db5a2111417526" member_type: VOTER }
I20260812 06:17:57.833122 17355 sys_catalog.cc:455] T 00000000000000000000000000000000 P d0125961fe0e410db2db5a2111417526 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "d0125961fe0e410db2db5a2111417526" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d0125961fe0e410db2db5a2111417526" member_type: VOTER } }
I20260812 06:17:57.833173 17356 sys_catalog.cc:455] T 00000000000000000000000000000000 P d0125961fe0e410db2db5a2111417526 [sys.catalog]: SysCatalogTable state changed. Reason: New leader d0125961fe0e410db2db5a2111417526. Latest consensus state: current_term: 1 leader_uuid: "d0125961fe0e410db2db5a2111417526" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d0125961fe0e410db2db5a2111417526" member_type: VOTER } }
I20260812 06:17:57.833335 17356 sys_catalog.cc:458] T 00000000000000000000000000000000 P d0125961fe0e410db2db5a2111417526 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:57.833630 17362 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:57.833868 17355 sys_catalog.cc:458] T 00000000000000000000000000000000 P d0125961fe0e410db2db5a2111417526 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:57.834621 17362 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:57.834936 16964 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:57.837458 17362 catalog_manager.cc:1383] Generated new cluster ID: b07fbfa21137452b99ff50edb8ffa864
I20260812 06:17:57.837551 17362 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:57.843492 17362 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:57.844146 17362 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:57.850178 17362 catalog_manager.cc:6092] T 00000000000000000000000000000000 P d0125961fe0e410db2db5a2111417526: Generated new TSK 0
I20260812 06:17:57.850391 17362 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:57.867463 16964 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:57.869777 17382 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:17:57.869851 17380 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:17:57.869812 16964 server_base.cc:1061] running on GCE node
W20260812 06:17:57.869781 17385 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:17:57.870278 16964 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:57.870327 16964 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:17:57.870347 16964 hybrid_clock.cc:648] HybridClock initialized: now 1786515477870346 us; error 0 us; skew 500 ppm
I20260812 06:17:57.871330 16964 webserver.cc:533] Webserver started at http://127.16.145.1:46155/ using document root <none> and password file <none>
I20260812 06:17:57.871508 16964 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:57.871649 16964 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:57.871732 16964 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:57.872166 16964 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515472001912-16964-0/minicluster-data/ts-0-root/instance:
uuid: "f53ddb04ec32460ab92fa5156d226894"
format_stamp: "Formatted at 2026-08-12 06:17:57 on dist-test-slave-sb2z"
I20260812 06:17:57.873849 16964 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:17:57.874936 17392 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:17:57.875247 16964 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:17:57.875316 16964 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515472001912-16964-0/minicluster-data/ts-0-root
uuid: "f53ddb04ec32460ab92fa5156d226894"
format_stamp: "Formatted at 2026-08-12 06:17:57 on dist-test-slave-sb2z"
I20260812 06:17:57.875379 16964 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515472001912-16964-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515472001912-16964-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515472001912-16964-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:17:57.908242 16964 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:57.908648 16964 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:57.908936 16964 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:57.909479 16964 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:57.909519 16964 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:57.909587 16964 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:57.909626 16964 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:57.914145 16964 rpc_server.cc:307] RPC server started. Bound to: 127.16.145.1:37067
I20260812 06:17:57.914175 17506 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.16.145.1:37067 every 8 connection(s)
I20260812 06:17:57.922802 17508 heartbeater.cc:344] Connected to a master server at 127.16.145.62:35513
I20260812 06:17:57.922931 17508 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:57.923243 17508 heartbeater.cc:507] Master 127.16.145.62:35513 requested a full tablet report, sending...
I20260812 06:17:57.924012 17296 ts_manager.cc:194] Registered new tserver with Master: f53ddb04ec32460ab92fa5156d226894 (127.16.145.1:37067)
I20260812 06:17:57.924691 16964 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.010091527s
I20260812 06:17:57.924751 17296 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:60916
I20260812 06:17:57.932045 17296 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:60924:
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:17:57.941668 17449 tablet_service.cc:1511] Processing CreateTablet for tablet 800067d70b7e42b981f8348c6667738f (DEFAULT_TABLE table=heavy-update-compaction-test [id=4d49eac792c447bd81b726f5dd9b27e3]), partition=
I20260812 06:17:57.941998 17449 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 800067d70b7e42b981f8348c6667738f. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:57.944401 17532 tablet_bootstrap.cc:492] T 800067d70b7e42b981f8348c6667738f P f53ddb04ec32460ab92fa5156d226894: Bootstrap starting.
I20260812 06:17:57.945325 17532 tablet_bootstrap.cc:654] T 800067d70b7e42b981f8348c6667738f P f53ddb04ec32460ab92fa5156d226894: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:57.946513 17532 tablet_bootstrap.cc:492] T 800067d70b7e42b981f8348c6667738f P f53ddb04ec32460ab92fa5156d226894: No bootstrap required, opened a new log
I20260812 06:17:57.946621 17532 ts_tablet_manager.cc:1403] T 800067d70b7e42b981f8348c6667738f P f53ddb04ec32460ab92fa5156d226894: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:57.947203 17532 raft_consensus.cc:359] T 800067d70b7e42b981f8348c6667738f P f53ddb04ec32460ab92fa5156d226894 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f53ddb04ec32460ab92fa5156d226894" member_type: VOTER last_known_addr { host: "127.16.145.1" port: 37067 } }
I20260812 06:17:57.947332 17532 raft_consensus.cc:385] T 800067d70b7e42b981f8348c6667738f P f53ddb04ec32460ab92fa5156d226894 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:57.947374 17532 raft_consensus.cc:740] T 800067d70b7e42b981f8348c6667738f P f53ddb04ec32460ab92fa5156d226894 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: f53ddb04ec32460ab92fa5156d226894, State: Initialized, Role: FOLLOWER
I20260812 06:17:57.947580 17532 consensus_queue.cc:260] T 800067d70b7e42b981f8348c6667738f P f53ddb04ec32460ab92fa5156d226894 [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: "f53ddb04ec32460ab92fa5156d226894" member_type: VOTER last_known_addr { host: "127.16.145.1" port: 37067 } }
I20260812 06:17:57.947679 17532 raft_consensus.cc:399] T 800067d70b7e42b981f8348c6667738f P f53ddb04ec32460ab92fa5156d226894 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:57.947706 17532 raft_consensus.cc:493] T 800067d70b7e42b981f8348c6667738f P f53ddb04ec32460ab92fa5156d226894 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:57.947742 17532 raft_consensus.cc:3060] T 800067d70b7e42b981f8348c6667738f P f53ddb04ec32460ab92fa5156d226894 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:57.948496 17532 raft_consensus.cc:515] T 800067d70b7e42b981f8348c6667738f P f53ddb04ec32460ab92fa5156d226894 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f53ddb04ec32460ab92fa5156d226894" member_type: VOTER last_known_addr { host: "127.16.145.1" port: 37067 } }
I20260812 06:17:57.948621 17532 leader_election.cc:304] T 800067d70b7e42b981f8348c6667738f P f53ddb04ec32460ab92fa5156d226894 [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: f53ddb04ec32460ab92fa5156d226894; no voters: 
I20260812 06:17:57.948792 17532 leader_election.cc:290] T 800067d70b7e42b981f8348c6667738f P f53ddb04ec32460ab92fa5156d226894 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:57.948959 17534 raft_consensus.cc:2804] T 800067d70b7e42b981f8348c6667738f P f53ddb04ec32460ab92fa5156d226894 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:57.949143 17532 ts_tablet_manager.cc:1434] T 800067d70b7e42b981f8348c6667738f P f53ddb04ec32460ab92fa5156d226894: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:17:57.949210 17534 raft_consensus.cc:697] T 800067d70b7e42b981f8348c6667738f P f53ddb04ec32460ab92fa5156d226894 [term 1 LEADER]: Becoming Leader. State: Replica: f53ddb04ec32460ab92fa5156d226894, State: Running, Role: LEADER
I20260812 06:17:57.949150 17508 heartbeater.cc:499] Master 127.16.145.62:35513 was elected leader, sending a full tablet report...
I20260812 06:17:57.949379 17534 consensus_queue.cc:237] T 800067d70b7e42b981f8348c6667738f P f53ddb04ec32460ab92fa5156d226894 [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: "f53ddb04ec32460ab92fa5156d226894" member_type: VOTER last_known_addr { host: "127.16.145.1" port: 37067 } }
I20260812 06:17:57.950845 17296 catalog_manager.cc:5719] T 800067d70b7e42b981f8348c6667738f P f53ddb04ec32460ab92fa5156d226894 reported cstate change: term changed from 0 to 1, leader changed from <none> to f53ddb04ec32460ab92fa5156d226894 (127.16.145.1). New cstate: current_term: 1 leader_uuid: "f53ddb04ec32460ab92fa5156d226894" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f53ddb04ec32460ab92fa5156d226894" member_type: VOTER last_known_addr { host: "127.16.145.1" port: 37067 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:58.012830 16964 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.055s	user 0.017s	sys 0.006s
I20260812 06:17:58.165254 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling FlushMRSOp(800067d70b7e42b981f8348c6667738f): perf score=19.054940
I20260812 06:17:58.334873 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: FlushMRSOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.169s	user 0.137s	sys 0.028s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":90,"dirs.run_cpu_time_us":203,"dirs.run_wall_time_us":945,"drs_written":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4,"lbm_write_time_us":43468,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:17:58.339073 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling LogGCOp(800067d70b7e42b981f8348c6667738f): free 20743880 bytes of WAL
I20260812 06:17:58.339407 17402 log_reader.cc:385] T 800067d70b7e42b981f8348c6667738f: removed 2 log segments from log reader
I20260812 06:17:58.339484 17402 log.cc:1079] T 800067d70b7e42b981f8348c6667738f P f53ddb04ec32460ab92fa5156d226894: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/800067d70b7e42b981f8348c6667738f/wal-000000001 (ops 1-6)
I20260812 06:17:58.339594 17402 log.cc:1079] T 800067d70b7e42b981f8348c6667738f P f53ddb04ec32460ab92fa5156d226894: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/800067d70b7e42b981f8348c6667738f/wal-000000002 (ops 7-11)
I20260812 06:17:58.344579 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: LogGCOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.005s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:17:58.345291 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling UndoDeltaBlockGCOp(800067d70b7e42b981f8348c6667738f): 16411393 bytes on disk
I20260812 06:17:58.345997 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: UndoDeltaBlockGCOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":102,"lbm_reads_lt_1ms":4}
I20260812 06:17:58.346763 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f): perf score=2.188937
I20260812 06:17:58.362550 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.016s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5148,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:58.363093 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling MajorDeltaCompactionOp(800067d70b7e42b981f8348c6667738f): perf score=1.000000
I20260812 06:17:58.527129 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: MajorDeltaCompactionOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.164s	user 0.107s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":963,"lbm_read_time_us":10764,"lbm_reads_lt_1ms":460,"lbm_write_time_us":26096,"lbm_writes_lt_1ms":443,"mutex_wait_us":103,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":28800,"thread_start_us":363,"threads_started":5,"update_count":2000}
I20260812 06:17:58.527920 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f): perf score=14.095187
I20260812 06:17:58.583510 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.055s	user 0.030s	sys 0.021s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":25694,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:58.584156 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling MajorDeltaCompactionOp(800067d70b7e42b981f8348c6667738f): perf score=1.000000
I20260812 06:17:58.747397 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: MajorDeltaCompactionOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.163s	user 0.106s	sys 0.053s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672156,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":570,"lbm_read_time_us":11262,"lbm_reads_lt_1ms":463,"lbm_write_time_us":28948,"lbm_writes_lt_1ms":443,"mutex_wait_us":25,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11136,"update_count":2000}
I20260812 06:17:58.748143 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f): perf score=11.118625
I20260812 06:17:58.789618 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.041s	user 0.024s	sys 0.015s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":17985,"lbm_writes_lt_1ms":313,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":1550}
I20260812 06:17:58.790364 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f): perf score=2.188937
I20260812 06:17:58.801788 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4499,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:58.802326 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling MajorDeltaCompactionOp(800067d70b7e42b981f8348c6667738f): perf score=1.000000
I20260812 06:17:58.959507 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: MajorDeltaCompactionOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.157s	user 0.112s	sys 0.042s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":321,"lbm_read_time_us":10209,"lbm_reads_lt_1ms":468,"lbm_write_time_us":32434,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":86,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":20480,"update_count":2000}
I20260812 06:17:58.960318 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f): perf score=10.126437
I20260812 06:17:59.002224 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.042s	user 0.021s	sys 0.015s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":17223,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:59.002802 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f): perf score=2.188937
I20260812 06:17:59.014585 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.012s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4480,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:59.015237 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling MajorDeltaCompactionOp(800067d70b7e42b981f8348c6667738f): perf score=1.000000
I20260812 06:17:59.167169 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: MajorDeltaCompactionOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.152s	user 0.108s	sys 0.044s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":223,"lbm_read_time_us":11099,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29977,"lbm_writes_lt_1ms":443,"mutex_wait_us":57,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7424,"update_count":2000}
I20260812 06:17:59.167845 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f): perf score=10.126437
I20260812 06:17:59.216984 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.049s	user 0.027s	sys 0.007s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15916,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:59.217545 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f): perf score=2.188937
I20260812 06:17:59.228943 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4576,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:59.229489 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling MajorDeltaCompactionOp(800067d70b7e42b981f8348c6667738f): perf score=1.000000
I20260812 06:17:59.361855 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: MajorDeltaCompactionOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.132s	user 0.087s	sys 0.045s 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":204,"lbm_read_time_us":10884,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26197,"lbm_writes_lt_1ms":443,"mutex_wait_us":40,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14208,"update_count":2000}
I20260812 06:17:59.363150 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f): perf score=10.126437
I20260812 06:17:59.403071 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.040s	user 0.029s	sys 0.007s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":13500,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:59.403743 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f): perf score=2.188937
I20260812 06:17:59.415138 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4330,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:59.415764 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling MajorDeltaCompactionOp(800067d70b7e42b981f8348c6667738f): perf score=1.000000
I20260812 06:17:59.574076 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: MajorDeltaCompactionOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.158s	user 0.106s	sys 0.051s 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":1314,"lbm_read_time_us":12884,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25813,"lbm_writes_lt_1ms":443,"mutex_wait_us":369,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:17:59.574697 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f): perf score=10.126437
I20260812 06:17:59.621959 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.047s	user 0.012s	sys 0.021s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16300,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:59.622574 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f): perf score=2.188937
I20260812 06:17:59.635723 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.013s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4544,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:59.636379 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling FlushMRSOp(800067d70b7e42b981f8348c6667738f): perf score=1.000000
I20260812 06:17:59.668001 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: FlushMRSOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.031s	user 0.027s	sys 0.004s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":75,"dirs.run_cpu_time_us":276,"dirs.run_wall_time_us":1442,"drs_written":1,"lbm_read_time_us":109,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1936,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:59.668633 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling LogGCOp(800067d70b7e42b981f8348c6667738f): free 108535447 bytes of WAL
I20260812 06:17:59.668879 17402 log_reader.cc:385] T 800067d70b7e42b981f8348c6667738f: removed 11 log segments from log reader
I20260812 06:17:59.668926 17402 log.cc:1079] T 800067d70b7e42b981f8348c6667738f P f53ddb04ec32460ab92fa5156d226894: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/800067d70b7e42b981f8348c6667738f/wal-000000003 (ops 12-16)
I20260812 06:17:59.668955 17402 log.cc:1079] T 800067d70b7e42b981f8348c6667738f P f53ddb04ec32460ab92fa5156d226894: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/800067d70b7e42b981f8348c6667738f/wal-000000004 (ops 17-20)
I20260812 06:17:59.669025 17402 log.cc:1079] T 800067d70b7e42b981f8348c6667738f P f53ddb04ec32460ab92fa5156d226894: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/800067d70b7e42b981f8348c6667738f/wal-000000005 (ops 21-25)
I20260812 06:17:59.669068 17402 log.cc:1079] T 800067d70b7e42b981f8348c6667738f P f53ddb04ec32460ab92fa5156d226894: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/800067d70b7e42b981f8348c6667738f/wal-000000006 (ops 26-30)
I20260812 06:17:59.669104 17402 log.cc:1079] T 800067d70b7e42b981f8348c6667738f P f53ddb04ec32460ab92fa5156d226894: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/800067d70b7e42b981f8348c6667738f/wal-000000007 (ops 31-34)
I20260812 06:17:59.669162 17402 log.cc:1079] T 800067d70b7e42b981f8348c6667738f P f53ddb04ec32460ab92fa5156d226894: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/800067d70b7e42b981f8348c6667738f/wal-000000008 (ops 35-39)
I20260812 06:17:59.669191 17402 log.cc:1079] T 800067d70b7e42b981f8348c6667738f P f53ddb04ec32460ab92fa5156d226894: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/800067d70b7e42b981f8348c6667738f/wal-000000009 (ops 40-44)
I20260812 06:17:59.669227 17402 log.cc:1079] T 800067d70b7e42b981f8348c6667738f P f53ddb04ec32460ab92fa5156d226894: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/800067d70b7e42b981f8348c6667738f/wal-000000010 (ops 45-49)
I20260812 06:17:59.669265 17402 log.cc:1079] T 800067d70b7e42b981f8348c6667738f P f53ddb04ec32460ab92fa5156d226894: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/800067d70b7e42b981f8348c6667738f/wal-000000011 (ops 50-54)
I20260812 06:17:59.669304 17402 log.cc:1079] T 800067d70b7e42b981f8348c6667738f P f53ddb04ec32460ab92fa5156d226894: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/800067d70b7e42b981f8348c6667738f/wal-000000012 (ops 55-59)
I20260812 06:17:59.669345 17402 log.cc:1079] T 800067d70b7e42b981f8348c6667738f P f53ddb04ec32460ab92fa5156d226894: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/800067d70b7e42b981f8348c6667738f/wal-000000013 (ops 60-64)
I20260812 06:17:59.695858 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: LogGCOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.027s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:17:59.696349 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling UndoDeltaBlockGCOp(800067d70b7e42b981f8348c6667738f): 447 bytes on disk
I20260812 06:17:59.696879 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: UndoDeltaBlockGCOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":73,"lbm_reads_lt_1ms":4}
I20260812 06:17:59.697417 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f): perf score=3.181125
I20260812 06:17:59.718636 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.021s	user 0.009s	sys 0.008s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":7872,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:59.719165 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f): perf score=2.188937
I20260812 06:17:59.741081 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.022s	user 0.006s	sys 0.014s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4216,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:59.741684 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling MajorDeltaCompactionOp(800067d70b7e42b981f8348c6667738f): perf score=1.000000
I20260812 06:17:59.939774 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: MajorDeltaCompactionOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.198s	user 0.149s	sys 0.048s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877330,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":755,"lbm_read_time_us":13933,"lbm_reads_lt_1ms":674,"lbm_write_time_us":32795,"lbm_writes_lt_1ms":643,"mutex_wait_us":586,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":6144,"thread_start_us":81,"threads_started":1,"update_count":3000}
I20260812 06:17:59.940526 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f): perf score=14.095187
I20260812 06:18:00.000615 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.060s	user 0.031s	sys 0.028s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20212,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:00.001448 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f): perf score=2.188937
I20260812 06:18:00.013197 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4526,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:00.013724 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling MajorDeltaCompactionOp(800067d70b7e42b981f8348c6667738f): perf score=1.000000
I20260812 06:18:00.201200 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: MajorDeltaCompactionOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.187s	user 0.115s	sys 0.071s 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":594,"lbm_read_time_us":13750,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32326,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:18:00.201834 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f): perf score=11.118625
I20260812 06:18:00.248750 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.047s	user 0.026s	sys 0.019s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":18424,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:00.249274 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f): perf score=2.188937
I20260812 06:18:00.270438 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.021s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5629,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:00.270962 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f): perf score=2.188937
I20260812 06:18:00.281935 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.011s	user 0.000s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4315,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:00.282532 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling MajorDeltaCompactionOp(800067d70b7e42b981f8348c6667738f): perf score=1.000000
I20260812 06:18:00.474915 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: MajorDeltaCompactionOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.192s	user 0.114s	sys 0.072s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":257,"lbm_read_time_us":11819,"lbm_reads_lt_1ms":573,"lbm_write_time_us":32659,"lbm_writes_lt_1ms":543,"mutex_wait_us":45,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10112,"update_count":2500}
I20260812 06:18:00.475667 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f): perf score=11.118625
I20260812 06:18:00.523249 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.047s	user 0.024s	sys 0.020s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":21739,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:00.523880 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f): perf score=2.188937
I20260812 06:18:00.548857 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.025s	user 0.007s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4933,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:00.549362 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f): perf score=2.188937
I20260812 06:18:00.560528 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4255,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:00.561177 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling MajorDeltaCompactionOp(800067d70b7e42b981f8348c6667738f): perf score=1.000000
I20260812 06:18:00.728425 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: MajorDeltaCompactionOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.167s	user 0.125s	sys 0.036s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774800,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":527,"lbm_read_time_us":10593,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30437,"lbm_writes_lt_1ms":543,"mutex_wait_us":58,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":17152,"update_count":2500}
I20260812 06:18:00.729216 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f): perf score=11.118625
I20260812 06:18:00.775620 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.046s	user 0.016s	sys 0.028s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":19163,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:18:00.776293 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f): perf score=2.188937
I20260812 06:18:00.788475 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.012s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4114,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:00.789019 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f): perf score=2.188937
I20260812 06:18:00.799322 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.010s	user 0.007s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3788,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:00.799903 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling MajorDeltaCompactionOp(800067d70b7e42b981f8348c6667738f): perf score=1.000000
I20260812 06:18:00.966961 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: MajorDeltaCompactionOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.167s	user 0.128s	sys 0.037s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774800,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":236,"lbm_read_time_us":12621,"lbm_reads_lt_1ms":573,"lbm_write_time_us":34294,"lbm_writes_lt_1ms":543,"mutex_wait_us":52,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9216,"update_count":2500}
I20260812 06:18:00.967844 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f): perf score=11.118625
I20260812 06:18:01.001777 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.034s	user 0.011s	sys 0.020s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":13837,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:01.002480 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f): perf score=2.188937
I20260812 06:18:01.029095 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.026s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4941,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:01.029779 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f): perf score=2.188937
I20260812 06:18:01.041864 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.012s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4334,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:01.042608 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling MajorDeltaCompactionOp(800067d70b7e42b981f8348c6667738f): perf score=1.000000
I20260812 06:18:01.207659 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: MajorDeltaCompactionOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.165s	user 0.104s	sys 0.048s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774801,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":678,"lbm_read_time_us":10869,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30262,"lbm_writes_lt_1ms":543,"mutex_wait_us":21,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":28544,"update_count":2500}
I20260812 06:18:01.208328 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f): perf score=14.095187
I20260812 06:18:01.260258 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.052s	user 0.043s	sys 0.008s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":22844,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:01.260867 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f): perf score=2.188937
I20260812 06:18:01.277091 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.016s	user 0.005s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5876,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:01.277700 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling FlushMRSOp(800067d70b7e42b981f8348c6667738f): perf score=1.000000
I20260812 06:18:01.320482 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: FlushMRSOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.043s	user 0.037s	sys 0.005s Metrics: {"bytes_written":1357580,"cfile_init":1,"dirs.queue_time_us":100,"dirs.run_cpu_time_us":212,"dirs.run_wall_time_us":1753,"drs_written":1,"lbm_read_time_us":138,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2104,"lbm_writes_lt_1ms":44,"peak_mem_usage":0,"rows_written":33}
I20260812 06:18:01.321417 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling LogGCOp(800067d70b7e42b981f8348c6667738f): free 136275175 bytes of WAL
I20260812 06:18:01.321667 17402 log_reader.cc:385] T 800067d70b7e42b981f8348c6667738f: removed 13 log segments from log reader
I20260812 06:18:01.321704 17402 log.cc:1079] T 800067d70b7e42b981f8348c6667738f P f53ddb04ec32460ab92fa5156d226894: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/800067d70b7e42b981f8348c6667738f/wal-000000014 (ops 65-69)
I20260812 06:18:01.321743 17402 log.cc:1079] T 800067d70b7e42b981f8348c6667738f P f53ddb04ec32460ab92fa5156d226894: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/800067d70b7e42b981f8348c6667738f/wal-000000015 (ops 70-74)
I20260812 06:18:01.321767 17402 log.cc:1079] T 800067d70b7e42b981f8348c6667738f P f53ddb04ec32460ab92fa5156d226894: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/800067d70b7e42b981f8348c6667738f/wal-000000016 (ops 75-79)
I20260812 06:18:01.321798 17402 log.cc:1079] T 800067d70b7e42b981f8348c6667738f P f53ddb04ec32460ab92fa5156d226894: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/800067d70b7e42b981f8348c6667738f/wal-000000017 (ops 80-84)
I20260812 06:18:01.321831 17402 log.cc:1079] T 800067d70b7e42b981f8348c6667738f P f53ddb04ec32460ab92fa5156d226894: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/800067d70b7e42b981f8348c6667738f/wal-000000018 (ops 85-89)
I20260812 06:18:01.321869 17402 log.cc:1079] T 800067d70b7e42b981f8348c6667738f P f53ddb04ec32460ab92fa5156d226894: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/800067d70b7e42b981f8348c6667738f/wal-000000019 (ops 90-94)
I20260812 06:18:01.321899 17402 log.cc:1079] T 800067d70b7e42b981f8348c6667738f P f53ddb04ec32460ab92fa5156d226894: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/800067d70b7e42b981f8348c6667738f/wal-000000020 (ops 95-99)
I20260812 06:18:01.321924 17402 log.cc:1079] T 800067d70b7e42b981f8348c6667738f P f53ddb04ec32460ab92fa5156d226894: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/800067d70b7e42b981f8348c6667738f/wal-000000021 (ops 100-104)
I20260812 06:18:01.321950 17402 log.cc:1079] T 800067d70b7e42b981f8348c6667738f P f53ddb04ec32460ab92fa5156d226894: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/800067d70b7e42b981f8348c6667738f/wal-000000022 (ops 105-108)
I20260812 06:18:01.321979 17402 log.cc:1079] T 800067d70b7e42b981f8348c6667738f P f53ddb04ec32460ab92fa5156d226894: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/800067d70b7e42b981f8348c6667738f/wal-000000023 (ops 109-113)
I20260812 06:18:01.322003 17402 log.cc:1079] T 800067d70b7e42b981f8348c6667738f P f53ddb04ec32460ab92fa5156d226894: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/800067d70b7e42b981f8348c6667738f/wal-000000024 (ops 114-118)
I20260812 06:18:01.322027 17402 log.cc:1079] T 800067d70b7e42b981f8348c6667738f P f53ddb04ec32460ab92fa5156d226894: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/800067d70b7e42b981f8348c6667738f/wal-000000025 (ops 119-123)
I20260812 06:18:01.322052 17402 log.cc:1079] T 800067d70b7e42b981f8348c6667738f P f53ddb04ec32460ab92fa5156d226894: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/800067d70b7e42b981f8348c6667738f/wal-000000026 (ops 124-128)
I20260812 06:18:01.358474 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: LogGCOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.037s	user 0.000s	sys 0.034s Metrics: {}
I20260812 06:18:01.359017 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling UndoDeltaBlockGCOp(800067d70b7e42b981f8348c6667738f): 508 bytes on disk
I20260812 06:18:01.359622 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: UndoDeltaBlockGCOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4}
I20260812 06:18:01.360214 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f): perf score=6.157687
I20260812 06:18:01.399560 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.039s	user 0.017s	sys 0.011s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":13457,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:18:01.400154 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling LogGCOp(800067d70b7e42b981f8348c6667738f): free 8767138 bytes of WAL
I20260812 06:18:01.400398 17402 log_reader.cc:385] T 800067d70b7e42b981f8348c6667738f: removed 1 log segments from log reader
I20260812 06:18:01.400454 17402 log.cc:1079] T 800067d70b7e42b981f8348c6667738f P f53ddb04ec32460ab92fa5156d226894: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/800067d70b7e42b981f8348c6667738f/wal-000000027 (ops 129-133)
I20260812 06:18:01.402480 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: LogGCOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:18:01.402864 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f): perf score=2.188937
I20260812 06:18:01.415781 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.013s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4785,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:01.416319 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling MajorDeltaCompactionOp(800067d70b7e42b981f8348c6667738f): perf score=1.000000
I20260812 06:18:01.635229 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: MajorDeltaCompactionOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.219s	user 0.158s	sys 0.060s Metrics: {"cfile_cache_miss":834,"cfile_cache_miss_bytes":37082161,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":617,"lbm_read_time_us":16880,"lbm_reads_lt_1ms":874,"lbm_write_time_us":44426,"lbm_writes_lt_1ms":843,"mutex_wait_us":97,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":4992,"thread_start_us":79,"threads_started":1,"update_count":4000}
I20260812 06:18:01.636027 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f): perf score=18.063937
I20260812 06:18:01.707473 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.071s	user 0.040s	sys 0.026s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":24248,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:01.708221 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f): perf score=2.188937
I20260812 06:18:01.719626 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.011s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4386,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:01.720134 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling MajorDeltaCompactionOp(800067d70b7e42b981f8348c6667738f): perf score=1.000000
I20260812 06:18:01.930749 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: MajorDeltaCompactionOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.210s	user 0.146s	sys 0.064s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877102,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1264,"lbm_read_time_us":15009,"lbm_reads_lt_1ms":672,"lbm_write_time_us":37142,"lbm_writes_lt_1ms":643,"mutex_wait_us":321,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":5888,"update_count":3000}
I20260812 06:18:01.931349 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f): perf score=14.095187
I20260812 06:18:01.997565 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.066s	user 0.036s	sys 0.022s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21431,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:01.998196 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f): perf score=2.188937
I20260812 06:18:02.009615 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4341,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:02.010198 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling MajorDeltaCompactionOp(800067d70b7e42b981f8348c6667738f): perf score=1.000000
I20260812 06:18:02.190146 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: MajorDeltaCompactionOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.180s	user 0.132s	sys 0.044s 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":196,"lbm_read_time_us":13641,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30767,"lbm_writes_lt_1ms":543,"mutex_wait_us":33,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11648,"update_count":2500}
I20260812 06:18:02.190909 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f): perf score=11.118625
I20260812 06:18:02.239353 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.048s	user 0.008s	sys 0.036s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":23695,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":310,"reinsert_count":0,"update_count":1550}
I20260812 06:18:02.240142 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f): perf score=2.188937
I20260812 06:18:02.257138 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.017s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4207,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:02.257639 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f): perf score=2.188937
I20260812 06:18:02.278270 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.020s	user 0.007s	sys 0.011s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3759,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:02.279063 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling MajorDeltaCompactionOp(800067d70b7e42b981f8348c6667738f): perf score=1.000000
I20260812 06:18:02.463002 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: MajorDeltaCompactionOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.184s	user 0.129s	sys 0.052s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":241,"lbm_read_time_us":12559,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30268,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14848,"update_count":2500}
I20260812 06:18:02.463759 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f): perf score=11.118625
I20260812 06:18:02.499128 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.035s	user 0.026s	sys 0.005s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":14908,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:02.499778 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f): perf score=2.188937
I20260812 06:18:02.523321 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.023s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5634,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:02.523829 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f): perf score=2.188937
I20260812 06:18:02.534749 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.011s	user 0.003s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4050,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:02.535267 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling MajorDeltaCompactionOp(800067d70b7e42b981f8348c6667738f): perf score=1.000000
I20260812 06:18:02.717064 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: MajorDeltaCompactionOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.182s	user 0.138s	sys 0.037s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774800,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":361,"lbm_read_time_us":10259,"lbm_reads_lt_1ms":573,"lbm_write_time_us":32248,"lbm_writes_lt_1ms":543,"mutex_wait_us":136,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6272,"update_count":2500}
I20260812 06:18:02.717913 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f): perf score=11.118625
I20260812 06:18:02.754572 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.036s	user 0.017s	sys 0.016s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16508,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":311,"reinsert_count":0,"update_count":1550}
I20260812 06:18:02.755244 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f): perf score=2.188937
I20260812 06:18:02.781034 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.026s	user 0.010s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6159,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":92,"reinsert_count":0,"update_count":450}
I20260812 06:18:02.781724 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f): perf score=2.188937
I20260812 06:18:02.797626 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.016s	user 0.008s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5782,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:02.798344 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling FlushMRSOp(800067d70b7e42b981f8348c6667738f): perf score=1.000000
I20260812 06:18:02.833202 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: FlushMRSOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.035s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1152512,"cfile_init":1,"dirs.queue_time_us":90,"dirs.run_cpu_time_us":298,"dirs.run_wall_time_us":1377,"drs_written":1,"lbm_read_time_us":78,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2292,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28,"spinlock_wait_cycles":1408}
I20260812 06:18:02.834030 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling LogGCOp(800067d70b7e42b981f8348c6667738f): free 112239554 bytes of WAL
I20260812 06:18:02.834270 17402 log_reader.cc:385] T 800067d70b7e42b981f8348c6667738f: removed 11 log segments from log reader
I20260812 06:18:02.834316 17402 log.cc:1079] T 800067d70b7e42b981f8348c6667738f P f53ddb04ec32460ab92fa5156d226894: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/800067d70b7e42b981f8348c6667738f/wal-000000028 (ops 134-138)
I20260812 06:18:02.834347 17402 log.cc:1079] T 800067d70b7e42b981f8348c6667738f P f53ddb04ec32460ab92fa5156d226894: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/800067d70b7e42b981f8348c6667738f/wal-000000029 (ops 139-143)
I20260812 06:18:02.834458 17402 log.cc:1079] T 800067d70b7e42b981f8348c6667738f P f53ddb04ec32460ab92fa5156d226894: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/800067d70b7e42b981f8348c6667738f/wal-000000030 (ops 144-148)
I20260812 06:18:02.834499 17402 log.cc:1079] T 800067d70b7e42b981f8348c6667738f P f53ddb04ec32460ab92fa5156d226894: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/800067d70b7e42b981f8348c6667738f/wal-000000031 (ops 149-153)
I20260812 06:18:02.834548 17402 log.cc:1079] T 800067d70b7e42b981f8348c6667738f P f53ddb04ec32460ab92fa5156d226894: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/800067d70b7e42b981f8348c6667738f/wal-000000032 (ops 154-158)
I20260812 06:18:02.834607 17402 log.cc:1079] T 800067d70b7e42b981f8348c6667738f P f53ddb04ec32460ab92fa5156d226894: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/800067d70b7e42b981f8348c6667738f/wal-000000033 (ops 159-162)
I20260812 06:18:02.834700 17402 log.cc:1079] T 800067d70b7e42b981f8348c6667738f P f53ddb04ec32460ab92fa5156d226894: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/800067d70b7e42b981f8348c6667738f/wal-000000034 (ops 163-167)
I20260812 06:18:02.834746 17402 log.cc:1079] T 800067d70b7e42b981f8348c6667738f P f53ddb04ec32460ab92fa5156d226894: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/800067d70b7e42b981f8348c6667738f/wal-000000035 (ops 168-172)
I20260812 06:18:02.834766 17402 log.cc:1079] T 800067d70b7e42b981f8348c6667738f P f53ddb04ec32460ab92fa5156d226894: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/800067d70b7e42b981f8348c6667738f/wal-000000036 (ops 173-177)
I20260812 06:18:02.834822 17402 log.cc:1079] T 800067d70b7e42b981f8348c6667738f P f53ddb04ec32460ab92fa5156d226894: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/800067d70b7e42b981f8348c6667738f/wal-000000037 (ops 178-182)
I20260812 06:18:02.834865 17402 log.cc:1079] T 800067d70b7e42b981f8348c6667738f P f53ddb04ec32460ab92fa5156d226894: Deleting log segment in path: /tmp/dist-test-taskxatoR4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515472001912-16964-0/minicluster-data/ts-0-root/wals/800067d70b7e42b981f8348c6667738f/wal-000000038 (ops 183-187)
I20260812 06:18:02.860515 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: LogGCOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.026s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:18:02.861066 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f): perf score=2.188937
I20260812 06:18:02.892817 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.032s	user 0.012s	sys 0.006s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6705,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:02.893450 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f): perf score=2.188937
I20260812 06:18:02.904626 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4329,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:02.905179 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling MajorDeltaCompactionOp(800067d70b7e42b981f8348c6667738f): perf score=1.000000
I20260812 06:18:03.134002 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: MajorDeltaCompactionOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.229s	user 0.156s	sys 0.070s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979858,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":474,"lbm_read_time_us":15765,"lbm_reads_lt_1ms":775,"lbm_write_time_us":39669,"lbm_writes_lt_1ms":743,"mutex_wait_us":101,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":2432,"thread_start_us":81,"threads_started":1,"update_count":3500}
I20260812 06:18:03.134790 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f): perf score=15.087375
I20260812 06:18:03.153486 16964 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.140s	user 1.838s	sys 0.200s
I20260812 06:18:03.189684 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.055s	user 0.032s	sys 0.020s Metrics: {"bytes_written":16820145,"delete_count":0,"lbm_write_time_us":24294,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:18:03.190281 17513 maintenance_manager.cc:419] P f53ddb04ec32460ab92fa5156d226894: Scheduling FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f): perf score=2.188937
I20260812 06:18:03.194937 16964 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.041s	user 0.001s	sys 0.000s
I20260812 06:18:03.195458 16964 tablet_server.cc:179] TabletServer@127.16.145.1:0 shutting down...
I20260812 06:18:03.203689 17402 maintenance_manager.cc:643] P f53ddb04ec32460ab92fa5156d226894: FlushDeltaMemStoresOp(800067d70b7e42b981f8348c6667738f) complete. Timing: real 0.013s	user 0.008s	sys 0.006s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5072,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:03.204262 16964 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:03.204474 16964 tablet_replica.cc:333] T 800067d70b7e42b981f8348c6667738f P f53ddb04ec32460ab92fa5156d226894: stopping tablet replica
I20260812 06:18:03.204661 16964 raft_consensus.cc:2243] T 800067d70b7e42b981f8348c6667738f P f53ddb04ec32460ab92fa5156d226894 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:03.204859 16964 raft_consensus.cc:2272] T 800067d70b7e42b981f8348c6667738f P f53ddb04ec32460ab92fa5156d226894 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:03.208348 16964 tablet_server.cc:196] TabletServer@127.16.145.1:0 shutdown complete.
I20260812 06:18:03.211234 16964 master.cc:562] Master@127.16.145.62:35513 shutting down...
I20260812 06:18:03.214736 16964 raft_consensus.cc:2243] T 00000000000000000000000000000000 P d0125961fe0e410db2db5a2111417526 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:03.214933 16964 raft_consensus.cc:2272] T 00000000000000000000000000000000 P d0125961fe0e410db2db5a2111417526 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:03.215008 16964 tablet_replica.cc:333] T 00000000000000000000000000000000 P d0125961fe0e410db2db5a2111417526: stopping tablet replica
I20260812 06:18:03.227641 16964 master.cc:584] Master@127.16.145.62:35513 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5537 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11312 ms total)

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