[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:19:02.451159 22060 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.21.139.62:39843
I20260812 06:19:02.452188 22060 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:19:02.453014 22060 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:02.459527 22073 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:02.459591 22060 server_base.cc:1061] running on GCE node
W20260812 06:19:02.459790 22075 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:02.459841 22072 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:02.460388 22060 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:02.460493 22060 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:02.460517 22060 hybrid_clock.cc:648] HybridClock initialized: now 1786515542460516 us; error 0 us; skew 500 ppm
I20260812 06:19:02.462121 22060 webserver.cc:533] Webserver started at http://127.21.139.62:36043/ using document root <none> and password file <none>
I20260812 06:19:02.462580 22060 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:02.462635 22060 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:02.462806 22060 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:02.464414 22060 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542440112-22060-0/minicluster-data/master-0-root/instance:
uuid: "1724d9b515ac42848e774d43196b1923"
format_stamp: "Formatted at 2026-08-12 06:19:02 on dist-test-slave-45dx"
I20260812 06:19:02.467451 22060 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:19:02.469385 22084 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:02.470319 22060 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:19:02.470465 22060 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542440112-22060-0/minicluster-data/master-0-root
uuid: "1724d9b515ac42848e774d43196b1923"
format_stamp: "Formatted at 2026-08-12 06:19:02 on dist-test-slave-45dx"
I20260812 06:19:02.470564 22060 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542440112-22060-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542440112-22060-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542440112-22060-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:02.498729 22060 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:02.499333 22060 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:19:02.499521 22060 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:02.506731 22181 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.21.139.62:39843 every 8 connection(s)
I20260812 06:19:02.506747 22060 rpc_server.cc:307] RPC server started. Bound to: 127.21.139.62:39843
I20260812 06:19:02.509011 22182 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:02.514175 22182 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 1724d9b515ac42848e774d43196b1923: Bootstrap starting.
I20260812 06:19:02.516453 22182 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 1724d9b515ac42848e774d43196b1923: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:02.517283 22182 log.cc:826] T 00000000000000000000000000000000 P 1724d9b515ac42848e774d43196b1923: Log is configured to *not* fsync() on all Append() calls
I20260812 06:19:02.518806 22182 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 1724d9b515ac42848e774d43196b1923: No bootstrap required, opened a new log
I20260812 06:19:02.521514 22182 raft_consensus.cc:359] T 00000000000000000000000000000000 P 1724d9b515ac42848e774d43196b1923 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1724d9b515ac42848e774d43196b1923" member_type: VOTER }
I20260812 06:19:02.521673 22182 raft_consensus.cc:385] T 00000000000000000000000000000000 P 1724d9b515ac42848e774d43196b1923 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:02.521718 22182 raft_consensus.cc:740] T 00000000000000000000000000000000 P 1724d9b515ac42848e774d43196b1923 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 1724d9b515ac42848e774d43196b1923, State: Initialized, Role: FOLLOWER
I20260812 06:19:02.522306 22182 consensus_queue.cc:260] T 00000000000000000000000000000000 P 1724d9b515ac42848e774d43196b1923 [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: "1724d9b515ac42848e774d43196b1923" member_type: VOTER }
I20260812 06:19:02.522445 22182 raft_consensus.cc:399] T 00000000000000000000000000000000 P 1724d9b515ac42848e774d43196b1923 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:02.522495 22182 raft_consensus.cc:493] T 00000000000000000000000000000000 P 1724d9b515ac42848e774d43196b1923 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:02.522578 22182 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 1724d9b515ac42848e774d43196b1923 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:02.523276 22182 raft_consensus.cc:515] T 00000000000000000000000000000000 P 1724d9b515ac42848e774d43196b1923 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1724d9b515ac42848e774d43196b1923" member_type: VOTER }
I20260812 06:19:02.523640 22182 leader_election.cc:304] T 00000000000000000000000000000000 P 1724d9b515ac42848e774d43196b1923 [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: 1724d9b515ac42848e774d43196b1923; no voters: 
I20260812 06:19:02.523890 22182 leader_election.cc:290] T 00000000000000000000000000000000 P 1724d9b515ac42848e774d43196b1923 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:02.524029 22192 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 1724d9b515ac42848e774d43196b1923 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:02.524341 22192 raft_consensus.cc:697] T 00000000000000000000000000000000 P 1724d9b515ac42848e774d43196b1923 [term 1 LEADER]: Becoming Leader. State: Replica: 1724d9b515ac42848e774d43196b1923, State: Running, Role: LEADER
I20260812 06:19:02.524744 22192 consensus_queue.cc:237] T 00000000000000000000000000000000 P 1724d9b515ac42848e774d43196b1923 [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: "1724d9b515ac42848e774d43196b1923" member_type: VOTER }
I20260812 06:19:02.524959 22182 sys_catalog.cc:565] T 00000000000000000000000000000000 P 1724d9b515ac42848e774d43196b1923 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:02.526639 22196 sys_catalog.cc:455] T 00000000000000000000000000000000 P 1724d9b515ac42848e774d43196b1923 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 1724d9b515ac42848e774d43196b1923. Latest consensus state: current_term: 1 leader_uuid: "1724d9b515ac42848e774d43196b1923" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1724d9b515ac42848e774d43196b1923" member_type: VOTER } }
I20260812 06:19:02.526646 22194 sys_catalog.cc:455] T 00000000000000000000000000000000 P 1724d9b515ac42848e774d43196b1923 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "1724d9b515ac42848e774d43196b1923" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1724d9b515ac42848e774d43196b1923" member_type: VOTER } }
I20260812 06:19:02.526818 22194 sys_catalog.cc:458] T 00000000000000000000000000000000 P 1724d9b515ac42848e774d43196b1923 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:02.526819 22196 sys_catalog.cc:458] T 00000000000000000000000000000000 P 1724d9b515ac42848e774d43196b1923 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:02.527230 22214 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:02.527329 22060 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:02.529412 22214 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:02.533798 22214 catalog_manager.cc:1383] Generated new cluster ID: b291aa39f4b64dc89444dd108ec9de93
I20260812 06:19:02.533862 22214 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:02.544643 22214 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:02.545444 22214 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:02.551517 22214 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 1724d9b515ac42848e774d43196b1923: Generated new TSK 0
I20260812 06:19:02.552071 22214 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:02.559893 22060 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:02.562675 22232 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:02.562752 22233 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:02.562809 22235 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:02.563069 22060 server_base.cc:1061] running on GCE node
I20260812 06:19:02.563258 22060 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:02.563313 22060 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:02.563347 22060 hybrid_clock.cc:648] HybridClock initialized: now 1786515542563346 us; error 0 us; skew 500 ppm
I20260812 06:19:02.564286 22060 webserver.cc:533] Webserver started at http://127.21.139.1:35127/ using document root <none> and password file <none>
I20260812 06:19:02.564503 22060 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:02.564577 22060 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:02.564656 22060 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:02.565033 22060 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542440112-22060-0/minicluster-data/ts-0-root/instance:
uuid: "7054727a9bd7475c86c3242a1650a1bc"
format_stamp: "Formatted at 2026-08-12 06:19:02 on dist-test-slave-45dx"
I20260812 06:19:02.566643 22060 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:19:02.567667 22242 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:02.567963 22060 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:19:02.568028 22060 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542440112-22060-0/minicluster-data/ts-0-root
uuid: "7054727a9bd7475c86c3242a1650a1bc"
format_stamp: "Formatted at 2026-08-12 06:19:02 on dist-test-slave-45dx"
I20260812 06:19:02.568115 22060 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542440112-22060-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542440112-22060-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542440112-22060-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:02.580965 22060 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:02.581611 22060 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:02.582129 22060 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:02.583025 22060 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:02.583077 22060 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:02.583145 22060 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:02.583190 22060 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:02.589892 22060 rpc_server.cc:307] RPC server started. Bound to: 127.21.139.1:35919
I20260812 06:19:02.589931 22350 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.21.139.1:35919 every 8 connection(s)
I20260812 06:19:02.603448 22352 heartbeater.cc:344] Connected to a master server at 127.21.139.62:39843
I20260812 06:19:02.603708 22352 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:02.604214 22352 heartbeater.cc:507] Master 127.21.139.62:39843 requested a full tablet report, sending...
I20260812 06:19:02.605737 22114 ts_manager.cc:194] Registered new tserver with Master: 7054727a9bd7475c86c3242a1650a1bc (127.21.139.1:35919)
I20260812 06:19:02.606282 22060 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.015742093s
I20260812 06:19:02.607316 22114 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:37020
I20260812 06:19:02.615542 22114 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:37028:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:02.629612 22290 tablet_service.cc:1511] Processing CreateTablet for tablet 7cc6f174f2cf4750806551a2d2598c7d (DEFAULT_TABLE table=heavy-update-compaction-test [id=c3861f11505f40868851bb15c007cb2f]), partition=
I20260812 06:19:02.630052 22290 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 7cc6f174f2cf4750806551a2d2598c7d. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:02.632524 22376 tablet_bootstrap.cc:492] T 7cc6f174f2cf4750806551a2d2598c7d P 7054727a9bd7475c86c3242a1650a1bc: Bootstrap starting.
I20260812 06:19:02.633486 22376 tablet_bootstrap.cc:654] T 7cc6f174f2cf4750806551a2d2598c7d P 7054727a9bd7475c86c3242a1650a1bc: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:02.634752 22376 tablet_bootstrap.cc:492] T 7cc6f174f2cf4750806551a2d2598c7d P 7054727a9bd7475c86c3242a1650a1bc: No bootstrap required, opened a new log
I20260812 06:19:02.634857 22376 ts_tablet_manager.cc:1403] T 7cc6f174f2cf4750806551a2d2598c7d P 7054727a9bd7475c86c3242a1650a1bc: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:02.635288 22376 raft_consensus.cc:359] T 7cc6f174f2cf4750806551a2d2598c7d P 7054727a9bd7475c86c3242a1650a1bc [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7054727a9bd7475c86c3242a1650a1bc" member_type: VOTER last_known_addr { host: "127.21.139.1" port: 35919 } }
I20260812 06:19:02.635386 22376 raft_consensus.cc:385] T 7cc6f174f2cf4750806551a2d2598c7d P 7054727a9bd7475c86c3242a1650a1bc [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:02.635437 22376 raft_consensus.cc:740] T 7cc6f174f2cf4750806551a2d2598c7d P 7054727a9bd7475c86c3242a1650a1bc [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 7054727a9bd7475c86c3242a1650a1bc, State: Initialized, Role: FOLLOWER
I20260812 06:19:02.635601 22376 consensus_queue.cc:260] T 7cc6f174f2cf4750806551a2d2598c7d P 7054727a9bd7475c86c3242a1650a1bc [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: "7054727a9bd7475c86c3242a1650a1bc" member_type: VOTER last_known_addr { host: "127.21.139.1" port: 35919 } }
I20260812 06:19:02.635689 22376 raft_consensus.cc:399] T 7cc6f174f2cf4750806551a2d2598c7d P 7054727a9bd7475c86c3242a1650a1bc [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:02.635744 22376 raft_consensus.cc:493] T 7cc6f174f2cf4750806551a2d2598c7d P 7054727a9bd7475c86c3242a1650a1bc [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:02.635799 22376 raft_consensus.cc:3060] T 7cc6f174f2cf4750806551a2d2598c7d P 7054727a9bd7475c86c3242a1650a1bc [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:02.636623 22376 raft_consensus.cc:515] T 7cc6f174f2cf4750806551a2d2598c7d P 7054727a9bd7475c86c3242a1650a1bc [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7054727a9bd7475c86c3242a1650a1bc" member_type: VOTER last_known_addr { host: "127.21.139.1" port: 35919 } }
I20260812 06:19:02.636781 22376 leader_election.cc:304] T 7cc6f174f2cf4750806551a2d2598c7d P 7054727a9bd7475c86c3242a1650a1bc [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: 7054727a9bd7475c86c3242a1650a1bc; no voters: 
I20260812 06:19:02.637044 22376 leader_election.cc:290] T 7cc6f174f2cf4750806551a2d2598c7d P 7054727a9bd7475c86c3242a1650a1bc [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:02.637156 22379 raft_consensus.cc:2804] T 7cc6f174f2cf4750806551a2d2598c7d P 7054727a9bd7475c86c3242a1650a1bc [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:02.637346 22379 raft_consensus.cc:697] T 7cc6f174f2cf4750806551a2d2598c7d P 7054727a9bd7475c86c3242a1650a1bc [term 1 LEADER]: Becoming Leader. State: Replica: 7054727a9bd7475c86c3242a1650a1bc, State: Running, Role: LEADER
I20260812 06:19:02.637437 22376 ts_tablet_manager.cc:1434] T 7cc6f174f2cf4750806551a2d2598c7d P 7054727a9bd7475c86c3242a1650a1bc: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:19:02.637560 22379 consensus_queue.cc:237] T 7cc6f174f2cf4750806551a2d2598c7d P 7054727a9bd7475c86c3242a1650a1bc [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: "7054727a9bd7475c86c3242a1650a1bc" member_type: VOTER last_known_addr { host: "127.21.139.1" port: 35919 } }
I20260812 06:19:02.637753 22352 heartbeater.cc:499] Master 127.21.139.62:39843 was elected leader, sending a full tablet report...
I20260812 06:19:02.640641 22114 catalog_manager.cc:5719] T 7cc6f174f2cf4750806551a2d2598c7d P 7054727a9bd7475c86c3242a1650a1bc reported cstate change: term changed from 0 to 1, leader changed from <none> to 7054727a9bd7475c86c3242a1650a1bc (127.21.139.1). New cstate: current_term: 1 leader_uuid: "7054727a9bd7475c86c3242a1650a1bc" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7054727a9bd7475c86c3242a1650a1bc" member_type: VOTER last_known_addr { host: "127.21.139.1" port: 35919 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:02.708978 22060 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.063s	user 0.024s	sys 0.008s
I20260812 06:19:02.840939 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling FlushMRSOp(7cc6f174f2cf4750806551a2d2598c7d): perf score=19.054940
I20260812 06:19:03.015550 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: FlushMRSOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.174s	user 0.145s	sys 0.023s Metrics: {"bytes_written":12307490,"cfile_init":1,"compiler_manager_pool.queue_time_us":183,"delete_count":0,"dirs.queue_time_us":63,"dirs.run_cpu_time_us":210,"dirs.run_wall_time_us":793,"drs_written":1,"lbm_read_time_us":65,"lbm_reads_lt_1ms":4,"lbm_write_time_us":43527,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":121,"threads_started":1,"update_count":1500}
I20260812 06:19:03.016654 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling LogGCOp(7cc6f174f2cf4750806551a2d2598c7d): free 20743880 bytes of WAL
I20260812 06:19:03.016942 22249 log_reader.cc:385] T 7cc6f174f2cf4750806551a2d2598c7d: removed 2 log segments from log reader
I20260812 06:19:03.017009 22249 log.cc:1079] T 7cc6f174f2cf4750806551a2d2598c7d P 7054727a9bd7475c86c3242a1650a1bc: Deleting log segment in path: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542440112-22060-0/minicluster-data/ts-0-root/wals/7cc6f174f2cf4750806551a2d2598c7d/wal-000000001 (ops 1-6)
I20260812 06:19:03.017057 22249 log.cc:1079] T 7cc6f174f2cf4750806551a2d2598c7d P 7054727a9bd7475c86c3242a1650a1bc: Deleting log segment in path: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542440112-22060-0/minicluster-data/ts-0-root/wals/7cc6f174f2cf4750806551a2d2598c7d/wal-000000002 (ops 7-11)
I20260812 06:19:03.023087 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: LogGCOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.006s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:19:03.023468 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d): perf score=2.188937
I20260812 06:19:03.057296 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.034s	user 0.010s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6082,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:03.057768 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling UndoDeltaBlockGCOp(7cc6f174f2cf4750806551a2d2598c7d): 16411395 bytes on disk
I20260812 06:19:03.058403 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: UndoDeltaBlockGCOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":68,"lbm_reads_lt_1ms":4}
I20260812 06:19:03.058808 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d): perf score=2.188937
I20260812 06:19:03.072705 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.014s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5596,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:03.073127 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling MajorDeltaCompactionOp(7cc6f174f2cf4750806551a2d2598c7d): perf score=1.000000
I20260812 06:19:03.234972 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: MajorDeltaCompactionOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.162s	user 0.125s	sys 0.036s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774807,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":460,"lbm_read_time_us":11707,"lbm_reads_lt_1ms":569,"lbm_write_time_us":27664,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10624,"thread_start_us":322,"threads_started":5,"update_count":2500}
I20260812 06:19:03.235531 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d): perf score=10.126437
I20260812 06:19:03.273684 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.038s	user 0.017s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15595,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:03.275560 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d): perf score=2.188937
I20260812 06:19:03.302958 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.027s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6673,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:03.303506 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d): perf score=2.188937
I20260812 06:19:03.313390 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3894,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:03.313803 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling MajorDeltaCompactionOp(7cc6f174f2cf4750806551a2d2598c7d): perf score=1.000000
I20260812 06:19:03.476069 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: MajorDeltaCompactionOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.162s	user 0.106s	sys 0.052s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774808,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":808,"lbm_read_time_us":10723,"lbm_reads_lt_1ms":573,"lbm_write_time_us":27317,"lbm_writes_lt_1ms":543,"mutex_wait_us":61,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:03.476722 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d): perf score=10.126437
I20260812 06:19:03.512583 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.036s	user 0.020s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14232,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:03.513098 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d): perf score=2.188937
I20260812 06:19:03.526245 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.013s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4754,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:03.526808 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling MajorDeltaCompactionOp(7cc6f174f2cf4750806551a2d2598c7d): perf score=1.000000
I20260812 06:19:03.648712 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: MajorDeltaCompactionOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.122s	user 0.088s	sys 0.034s 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":492,"lbm_read_time_us":7136,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24562,"lbm_writes_lt_1ms":443,"mutex_wait_us":20,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":97664,"update_count":2000}
I20260812 06:19:03.649200 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d): perf score=10.126437
I20260812 06:19:03.684690 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.035s	user 0.017s	sys 0.017s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14892,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:03.685390 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d): perf score=2.188937
I20260812 06:19:03.697134 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4108,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:03.697726 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling MajorDeltaCompactionOp(7cc6f174f2cf4750806551a2d2598c7d): perf score=1.000000
I20260812 06:19:03.807088 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: MajorDeltaCompactionOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.109s	user 0.100s	sys 0.007s 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":286,"lbm_read_time_us":7876,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21170,"lbm_writes_lt_1ms":443,"mutex_wait_us":3,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:19:03.807698 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d): perf score=10.126437
I20260812 06:19:03.853897 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.046s	user 0.029s	sys 0.015s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16814,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:03.854385 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d): perf score=2.188937
I20260812 06:19:03.864472 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102660,"delete_count":0,"lbm_write_time_us":3985,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:03.864893 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling MajorDeltaCompactionOp(7cc6f174f2cf4750806551a2d2598c7d): perf score=1.000000
I20260812 06:19:03.997596 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: MajorDeltaCompactionOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.133s	user 0.076s	sys 0.056s 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":184,"lbm_read_time_us":10645,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21649,"lbm_writes_lt_1ms":443,"mutex_wait_us":39,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9472,"update_count":2000}
I20260812 06:19:03.998087 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d): perf score=10.126437
I20260812 06:19:04.044600 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.046s	user 0.026s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16164,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:04.045069 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d): perf score=2.188937
I20260812 06:19:04.055141 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3957,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:04.055794 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling MajorDeltaCompactionOp(7cc6f174f2cf4750806551a2d2598c7d): perf score=1.000000
I20260812 06:19:04.179704 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: MajorDeltaCompactionOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.124s	user 0.104s	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":144,"lbm_read_time_us":9174,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23630,"lbm_writes_lt_1ms":443,"mutex_wait_us":42,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:19:04.180486 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d): perf score=10.126437
I20260812 06:19:04.222942 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.042s	user 0.031s	sys 0.005s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16110,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:04.223410 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d): perf score=2.188937
I20260812 06:19:04.233659 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4019,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:04.234055 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling FlushMRSOp(7cc6f174f2cf4750806551a2d2598c7d): perf score=1.000000
I20260812 06:19:04.272541 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: FlushMRSOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.038s	user 0.030s	sys 0.003s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":6892,"dirs.run_cpu_time_us":202,"dirs.run_wall_time_us":1776,"drs_written":1,"lbm_read_time_us":81,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1869,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:04.273525 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling LogGCOp(7cc6f174f2cf4750806551a2d2598c7d): free 120100324 bytes of WAL
I20260812 06:19:04.273808 22249 log_reader.cc:385] T 7cc6f174f2cf4750806551a2d2598c7d: removed 12 log segments from log reader
I20260812 06:19:04.273873 22249 log.cc:1079] T 7cc6f174f2cf4750806551a2d2598c7d P 7054727a9bd7475c86c3242a1650a1bc: Deleting log segment in path: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542440112-22060-0/minicluster-data/ts-0-root/wals/7cc6f174f2cf4750806551a2d2598c7d/wal-000000003 (ops 12-16)
I20260812 06:19:04.273981 22249 log.cc:1079] T 7cc6f174f2cf4750806551a2d2598c7d P 7054727a9bd7475c86c3242a1650a1bc: Deleting log segment in path: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542440112-22060-0/minicluster-data/ts-0-root/wals/7cc6f174f2cf4750806551a2d2598c7d/wal-000000004 (ops 17-20)
I20260812 06:19:04.274020 22249 log.cc:1079] T 7cc6f174f2cf4750806551a2d2598c7d P 7054727a9bd7475c86c3242a1650a1bc: Deleting log segment in path: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542440112-22060-0/minicluster-data/ts-0-root/wals/7cc6f174f2cf4750806551a2d2598c7d/wal-000000005 (ops 21-25)
I20260812 06:19:04.274044 22249 log.cc:1079] T 7cc6f174f2cf4750806551a2d2598c7d P 7054727a9bd7475c86c3242a1650a1bc: Deleting log segment in path: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542440112-22060-0/minicluster-data/ts-0-root/wals/7cc6f174f2cf4750806551a2d2598c7d/wal-000000006 (ops 26-30)
I20260812 06:19:04.274083 22249 log.cc:1079] T 7cc6f174f2cf4750806551a2d2598c7d P 7054727a9bd7475c86c3242a1650a1bc: Deleting log segment in path: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542440112-22060-0/minicluster-data/ts-0-root/wals/7cc6f174f2cf4750806551a2d2598c7d/wal-000000007 (ops 31-35)
I20260812 06:19:04.274113 22249 log.cc:1079] T 7cc6f174f2cf4750806551a2d2598c7d P 7054727a9bd7475c86c3242a1650a1bc: Deleting log segment in path: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542440112-22060-0/minicluster-data/ts-0-root/wals/7cc6f174f2cf4750806551a2d2598c7d/wal-000000008 (ops 36-40)
I20260812 06:19:04.274137 22249 log.cc:1079] T 7cc6f174f2cf4750806551a2d2598c7d P 7054727a9bd7475c86c3242a1650a1bc: Deleting log segment in path: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542440112-22060-0/minicluster-data/ts-0-root/wals/7cc6f174f2cf4750806551a2d2598c7d/wal-000000009 (ops 41-45)
I20260812 06:19:04.274164 22249 log.cc:1079] T 7cc6f174f2cf4750806551a2d2598c7d P 7054727a9bd7475c86c3242a1650a1bc: Deleting log segment in path: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542440112-22060-0/minicluster-data/ts-0-root/wals/7cc6f174f2cf4750806551a2d2598c7d/wal-000000010 (ops 46-50)
I20260812 06:19:04.274199 22249 log.cc:1079] T 7cc6f174f2cf4750806551a2d2598c7d P 7054727a9bd7475c86c3242a1650a1bc: Deleting log segment in path: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542440112-22060-0/minicluster-data/ts-0-root/wals/7cc6f174f2cf4750806551a2d2598c7d/wal-000000011 (ops 51-54)
I20260812 06:19:04.274230 22249 log.cc:1079] T 7cc6f174f2cf4750806551a2d2598c7d P 7054727a9bd7475c86c3242a1650a1bc: Deleting log segment in path: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542440112-22060-0/minicluster-data/ts-0-root/wals/7cc6f174f2cf4750806551a2d2598c7d/wal-000000012 (ops 55-59)
I20260812 06:19:04.274258 22249 log.cc:1079] T 7cc6f174f2cf4750806551a2d2598c7d P 7054727a9bd7475c86c3242a1650a1bc: Deleting log segment in path: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542440112-22060-0/minicluster-data/ts-0-root/wals/7cc6f174f2cf4750806551a2d2598c7d/wal-000000013 (ops 60-64)
I20260812 06:19:04.274282 22249 log.cc:1079] T 7cc6f174f2cf4750806551a2d2598c7d P 7054727a9bd7475c86c3242a1650a1bc: Deleting log segment in path: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542440112-22060-0/minicluster-data/ts-0-root/wals/7cc6f174f2cf4750806551a2d2598c7d/wal-000000014 (ops 65-68)
I20260812 06:19:04.299682 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: LogGCOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.026s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:19:04.300130 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling UndoDeltaBlockGCOp(7cc6f174f2cf4750806551a2d2598c7d): 472 bytes on disk
I20260812 06:19:04.300639 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: UndoDeltaBlockGCOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":68,"lbm_reads_lt_1ms":4}
I20260812 06:19:04.301186 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d): perf score=3.181125
I20260812 06:19:04.312557 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.011s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4512899,"delete_count":0,"lbm_write_time_us":4542,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:04.312987 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d): perf score=2.188937
I20260812 06:19:04.321956 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.009s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3444,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:04.322305 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling MajorDeltaCompactionOp(7cc6f174f2cf4750806551a2d2598c7d): perf score=1.000000
I20260812 06:19:04.488649 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: MajorDeltaCompactionOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.166s	user 0.115s	sys 0.044s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877324,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":370,"lbm_read_time_us":12754,"lbm_reads_lt_1ms":674,"lbm_write_time_us":31045,"lbm_writes_lt_1ms":643,"mutex_wait_us":80,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2560,"thread_start_us":79,"threads_started":1,"update_count":3000}
I20260812 06:19:04.489688 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d): perf score=14.095187
I20260812 06:19:04.534298 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.044s	user 0.030s	sys 0.012s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19069,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:04.534826 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d): perf score=2.188937
I20260812 06:19:04.549036 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.014s	user 0.012s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5512,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:04.549453 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling MajorDeltaCompactionOp(7cc6f174f2cf4750806551a2d2598c7d): perf score=1.000000
I20260812 06:19:04.701512 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: MajorDeltaCompactionOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.152s	user 0.127s	sys 0.025s 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":257,"lbm_read_time_us":10569,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29783,"lbm_writes_lt_1ms":543,"mutex_wait_us":40,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8832,"update_count":2500}
I20260812 06:19:04.706461 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d): perf score=11.118625
I20260812 06:19:04.743381 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.037s	user 0.026s	sys 0.008s Metrics: {"bytes_written":12594660,"delete_count":0,"lbm_write_time_us":15786,"lbm_writes_lt_1ms":310,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":1535}
I20260812 06:19:04.743965 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d): perf score=2.188937
I20260812 06:19:04.758368 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3815484,"delete_count":0,"lbm_write_time_us":5511,"lbm_writes_lt_1ms":96,"reinsert_count":0,"update_count":465}
I20260812 06:19:04.758977 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling MajorDeltaCompactionOp(7cc6f174f2cf4750806551a2d2598c7d): perf score=1.000000
I20260812 06:19:04.913303 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: MajorDeltaCompactionOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.154s	user 0.096s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672272,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":160,"lbm_read_time_us":8392,"lbm_reads_lt_1ms":468,"lbm_write_time_us":26704,"lbm_writes_lt_1ms":443,"mutex_wait_us":50,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13952,"update_count":2000}
I20260812 06:19:04.913996 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d): perf score=14.095187
I20260812 06:19:04.974247 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.060s	user 0.043s	sys 0.011s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":21251,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:04.974798 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d): perf score=2.188937
I20260812 06:19:04.985496 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4239,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:04.985913 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling MajorDeltaCompactionOp(7cc6f174f2cf4750806551a2d2598c7d): perf score=1.000000
I20260812 06:19:05.162132 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: MajorDeltaCompactionOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.176s	user 0.124s	sys 0.052s 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":1142,"lbm_read_time_us":13616,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28668,"lbm_writes_lt_1ms":543,"mutex_wait_us":257,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":29184,"update_count":2500}
I20260812 06:19:05.162967 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d): perf score=10.126437
I20260812 06:19:05.198457 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.035s	user 0.013s	sys 0.020s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17271,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:19:05.199007 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d): perf score=2.188937
I20260812 06:19:05.213196 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.014s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5341,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:05.213713 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling MajorDeltaCompactionOp(7cc6f174f2cf4750806551a2d2598c7d): perf score=1.000000
I20260812 06:19:05.334911 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: MajorDeltaCompactionOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.121s	user 0.099s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":964,"lbm_read_time_us":7713,"lbm_reads_lt_1ms":464,"lbm_write_time_us":22599,"lbm_writes_lt_1ms":443,"mutex_wait_us":328,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":30208,"update_count":2000}
I20260812 06:19:05.335449 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d): perf score=10.126437
I20260812 06:19:05.377157 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.041s	user 0.019s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17552,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:05.377681 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d): perf score=2.188937
I20260812 06:19:05.391665 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5380,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:05.392153 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling MajorDeltaCompactionOp(7cc6f174f2cf4750806551a2d2598c7d): perf score=1.000000
I20260812 06:19:05.517778 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: MajorDeltaCompactionOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.125s	user 0.089s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1007,"lbm_read_time_us":9418,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22960,"lbm_writes_lt_1ms":443,"mutex_wait_us":328,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:19:05.518265 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d): perf score=10.126437
I20260812 06:19:05.569993 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.052s	user 0.029s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16788,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:05.570456 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d): perf score=2.188937
I20260812 06:19:05.580513 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.010s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3911,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:05.581118 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling FlushMRSOp(7cc6f174f2cf4750806551a2d2598c7d): perf score=1.000000
I20260812 06:19:05.609548 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: FlushMRSOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.028s	user 0.026s	sys 0.000s Metrics: {"bytes_written":1152514,"cfile_init":1,"dirs.queue_time_us":55,"dirs.run_cpu_time_us":249,"dirs.run_wall_time_us":1418,"drs_written":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1335,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:05.610340 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling LogGCOp(7cc6f174f2cf4750806551a2d2598c7d): free 112692324 bytes of WAL
I20260812 06:19:05.610596 22249 log_reader.cc:385] T 7cc6f174f2cf4750806551a2d2598c7d: removed 11 log segments from log reader
I20260812 06:19:05.610659 22249 log.cc:1079] T 7cc6f174f2cf4750806551a2d2598c7d P 7054727a9bd7475c86c3242a1650a1bc: Deleting log segment in path: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542440112-22060-0/minicluster-data/ts-0-root/wals/7cc6f174f2cf4750806551a2d2598c7d/wal-000000015 (ops 69-73)
I20260812 06:19:05.610697 22249 log.cc:1079] T 7cc6f174f2cf4750806551a2d2598c7d P 7054727a9bd7475c86c3242a1650a1bc: Deleting log segment in path: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542440112-22060-0/minicluster-data/ts-0-root/wals/7cc6f174f2cf4750806551a2d2598c7d/wal-000000016 (ops 74-78)
I20260812 06:19:05.610728 22249 log.cc:1079] T 7cc6f174f2cf4750806551a2d2598c7d P 7054727a9bd7475c86c3242a1650a1bc: Deleting log segment in path: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542440112-22060-0/minicluster-data/ts-0-root/wals/7cc6f174f2cf4750806551a2d2598c7d/wal-000000017 (ops 79-83)
I20260812 06:19:05.610752 22249 log.cc:1079] T 7cc6f174f2cf4750806551a2d2598c7d P 7054727a9bd7475c86c3242a1650a1bc: Deleting log segment in path: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542440112-22060-0/minicluster-data/ts-0-root/wals/7cc6f174f2cf4750806551a2d2598c7d/wal-000000018 (ops 84-88)
I20260812 06:19:05.610788 22249 log.cc:1079] T 7cc6f174f2cf4750806551a2d2598c7d P 7054727a9bd7475c86c3242a1650a1bc: Deleting log segment in path: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542440112-22060-0/minicluster-data/ts-0-root/wals/7cc6f174f2cf4750806551a2d2598c7d/wal-000000019 (ops 89-93)
I20260812 06:19:05.610813 22249 log.cc:1079] T 7cc6f174f2cf4750806551a2d2598c7d P 7054727a9bd7475c86c3242a1650a1bc: Deleting log segment in path: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542440112-22060-0/minicluster-data/ts-0-root/wals/7cc6f174f2cf4750806551a2d2598c7d/wal-000000020 (ops 94-98)
I20260812 06:19:05.610844 22249 log.cc:1079] T 7cc6f174f2cf4750806551a2d2598c7d P 7054727a9bd7475c86c3242a1650a1bc: Deleting log segment in path: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542440112-22060-0/minicluster-data/ts-0-root/wals/7cc6f174f2cf4750806551a2d2598c7d/wal-000000021 (ops 99-103)
I20260812 06:19:05.610867 22249 log.cc:1079] T 7cc6f174f2cf4750806551a2d2598c7d P 7054727a9bd7475c86c3242a1650a1bc: Deleting log segment in path: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542440112-22060-0/minicluster-data/ts-0-root/wals/7cc6f174f2cf4750806551a2d2598c7d/wal-000000022 (ops 104-108)
I20260812 06:19:05.610898 22249 log.cc:1079] T 7cc6f174f2cf4750806551a2d2598c7d P 7054727a9bd7475c86c3242a1650a1bc: Deleting log segment in path: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542440112-22060-0/minicluster-data/ts-0-root/wals/7cc6f174f2cf4750806551a2d2598c7d/wal-000000023 (ops 109-113)
I20260812 06:19:05.610940 22249 log.cc:1079] T 7cc6f174f2cf4750806551a2d2598c7d P 7054727a9bd7475c86c3242a1650a1bc: Deleting log segment in path: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542440112-22060-0/minicluster-data/ts-0-root/wals/7cc6f174f2cf4750806551a2d2598c7d/wal-000000024 (ops 114-118)
I20260812 06:19:05.610975 22249 log.cc:1079] T 7cc6f174f2cf4750806551a2d2598c7d P 7054727a9bd7475c86c3242a1650a1bc: Deleting log segment in path: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542440112-22060-0/minicluster-data/ts-0-root/wals/7cc6f174f2cf4750806551a2d2598c7d/wal-000000025 (ops 119-123)
I20260812 06:19:05.635269 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: LogGCOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.025s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:19:05.635859 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling UndoDeltaBlockGCOp(7cc6f174f2cf4750806551a2d2598c7d): 446 bytes on disk
I20260812 06:19:05.636521 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: UndoDeltaBlockGCOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":89,"lbm_reads_lt_1ms":4}
I20260812 06:19:05.637346 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d): perf score=2.188937
I20260812 06:19:05.657979 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.020s	user 0.009s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5530,"lbm_writes_lt_1ms":103,"mutex_wait_us":2,"reinsert_count":0,"update_count":500}
I20260812 06:19:05.658526 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling LogGCOp(7cc6f174f2cf4750806551a2d2598c7d): free 12017983 bytes of WAL
I20260812 06:19:05.658761 22249 log_reader.cc:385] T 7cc6f174f2cf4750806551a2d2598c7d: removed 1 log segments from log reader
I20260812 06:19:05.658808 22249 log.cc:1079] T 7cc6f174f2cf4750806551a2d2598c7d P 7054727a9bd7475c86c3242a1650a1bc: Deleting log segment in path: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542440112-22060-0/minicluster-data/ts-0-root/wals/7cc6f174f2cf4750806551a2d2598c7d/wal-000000026 (ops 124-128)
I20260812 06:19:05.661031 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: LogGCOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.002s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:19:05.661345 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d): perf score=2.188937
I20260812 06:19:05.672245 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.011s	user 0.000s	sys 0.009s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4025,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:05.672778 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling MajorDeltaCompactionOp(7cc6f174f2cf4750806551a2d2598c7d): perf score=1.000000
I20260812 06:19:05.845299 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: MajorDeltaCompactionOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.172s	user 0.118s	sys 0.053s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877337,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":405,"lbm_read_time_us":12232,"lbm_reads_lt_1ms":674,"lbm_write_time_us":36518,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2944,"thread_start_us":93,"threads_started":1,"update_count":3000}
I20260812 06:19:05.845947 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d): perf score=14.095187
I20260812 06:19:05.900061 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.054s	user 0.028s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24606,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:05.900664 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d): perf score=2.188937
I20260812 06:19:05.913085 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4256,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:05.913535 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling MajorDeltaCompactionOp(7cc6f174f2cf4750806551a2d2598c7d): perf score=1.000000
I20260812 06:19:06.069276 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: MajorDeltaCompactionOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.156s	user 0.098s	sys 0.054s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":204,"lbm_read_time_us":10102,"lbm_reads_lt_1ms":568,"lbm_write_time_us":30791,"lbm_writes_lt_1ms":543,"mutex_wait_us":2,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":15616,"update_count":2500}
I20260812 06:19:06.070129 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d): perf score=11.118625
I20260812 06:19:06.107933 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.038s	user 0.025s	sys 0.009s Metrics: {"bytes_written":12799774,"delete_count":0,"lbm_write_time_us":16133,"lbm_writes_lt_1ms":315,"reinsert_count":0,"update_count":1560}
I20260812 06:19:06.108636 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d): perf score=2.188937
I20260812 06:19:06.121352 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.012s	user 0.006s	sys 0.005s Metrics: {"bytes_written":3610355,"delete_count":0,"lbm_write_time_us":4673,"lbm_writes_lt_1ms":91,"reinsert_count":0,"update_count":440}
I20260812 06:19:06.121803 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling MajorDeltaCompactionOp(7cc6f174f2cf4750806551a2d2598c7d): perf score=1.000000
I20260812 06:19:06.274722 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: MajorDeltaCompactionOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.153s	user 0.111s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672257,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":952,"lbm_read_time_us":10084,"lbm_reads_lt_1ms":468,"lbm_write_time_us":23528,"lbm_writes_lt_1ms":443,"mutex_wait_us":277,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11520,"update_count":2000}
I20260812 06:19:06.275301 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d): perf score=14.095187
I20260812 06:19:06.327454 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.052s	user 0.031s	sys 0.009s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18765,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:06.328007 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d): perf score=2.188937
I20260812 06:19:06.350564 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.022s	user 0.009s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5897,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:06.351166 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling MajorDeltaCompactionOp(7cc6f174f2cf4750806551a2d2598c7d): perf score=1.000000
I20260812 06:19:06.534866 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: MajorDeltaCompactionOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.183s	user 0.117s	sys 0.056s 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":298,"lbm_read_time_us":12362,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29685,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:19:06.535701 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d): perf score=14.095187
I20260812 06:19:06.585678 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.050s	user 0.038s	sys 0.004s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19278,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:06.586216 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d): perf score=2.188937
I20260812 06:19:06.601505 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.015s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5745,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:06.602072 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling MajorDeltaCompactionOp(7cc6f174f2cf4750806551a2d2598c7d): perf score=1.000000
I20260812 06:19:06.764066 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: MajorDeltaCompactionOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.162s	user 0.111s	sys 0.045s 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":598,"lbm_read_time_us":10140,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29254,"lbm_writes_lt_1ms":543,"mutex_wait_us":272,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:06.764732 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d): perf score=11.118625
I20260812 06:19:06.799081 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.034s	user 0.022s	sys 0.009s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":15271,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:06.799577 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d): perf score=2.188937
I20260812 06:19:06.818615 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.019s	user 0.004s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5197,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:06.819221 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling MajorDeltaCompactionOp(7cc6f174f2cf4750806551a2d2598c7d): perf score=1.000000
I20260812 06:19:06.943956 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: MajorDeltaCompactionOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.124s	user 0.096s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672269,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":775,"lbm_read_time_us":8574,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24200,"lbm_writes_lt_1ms":443,"mutex_wait_us":301,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2000}
I20260812 06:19:06.944754 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d): perf score=10.126437
I20260812 06:19:06.990125 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.045s	user 0.028s	sys 0.007s Metrics: {"bytes_written":12307498,"delete_count":0,"lbm_write_time_us":17439,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:06.990660 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d): perf score=2.188937
I20260812 06:19:07.004997 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.014s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5400,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:07.005571 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling FlushMRSOp(7cc6f174f2cf4750806551a2d2598c7d): perf score=1.000000
I20260812 06:19:07.036679 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: FlushMRSOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.031s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1193505,"cfile_init":1,"dirs.queue_time_us":71,"dirs.run_cpu_time_us":237,"dirs.run_wall_time_us":1383,"drs_written":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1427,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:19:07.037400 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling LogGCOp(7cc6f174f2cf4750806551a2d2598c7d): free 112692563 bytes of WAL
I20260812 06:19:07.037659 22249 log_reader.cc:385] T 7cc6f174f2cf4750806551a2d2598c7d: removed 11 log segments from log reader
I20260812 06:19:07.037717 22249 log.cc:1079] T 7cc6f174f2cf4750806551a2d2598c7d P 7054727a9bd7475c86c3242a1650a1bc: Deleting log segment in path: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542440112-22060-0/minicluster-data/ts-0-root/wals/7cc6f174f2cf4750806551a2d2598c7d/wal-000000027 (ops 129-133)
I20260812 06:19:07.037758 22249 log.cc:1079] T 7cc6f174f2cf4750806551a2d2598c7d P 7054727a9bd7475c86c3242a1650a1bc: Deleting log segment in path: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542440112-22060-0/minicluster-data/ts-0-root/wals/7cc6f174f2cf4750806551a2d2598c7d/wal-000000028 (ops 134-138)
I20260812 06:19:07.037794 22249 log.cc:1079] T 7cc6f174f2cf4750806551a2d2598c7d P 7054727a9bd7475c86c3242a1650a1bc: Deleting log segment in path: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542440112-22060-0/minicluster-data/ts-0-root/wals/7cc6f174f2cf4750806551a2d2598c7d/wal-000000029 (ops 139-143)
I20260812 06:19:07.037825 22249 log.cc:1079] T 7cc6f174f2cf4750806551a2d2598c7d P 7054727a9bd7475c86c3242a1650a1bc: Deleting log segment in path: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542440112-22060-0/minicluster-data/ts-0-root/wals/7cc6f174f2cf4750806551a2d2598c7d/wal-000000030 (ops 144-148)
I20260812 06:19:07.037854 22249 log.cc:1079] T 7cc6f174f2cf4750806551a2d2598c7d P 7054727a9bd7475c86c3242a1650a1bc: Deleting log segment in path: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542440112-22060-0/minicluster-data/ts-0-root/wals/7cc6f174f2cf4750806551a2d2598c7d/wal-000000031 (ops 149-153)
I20260812 06:19:07.037883 22249 log.cc:1079] T 7cc6f174f2cf4750806551a2d2598c7d P 7054727a9bd7475c86c3242a1650a1bc: Deleting log segment in path: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542440112-22060-0/minicluster-data/ts-0-root/wals/7cc6f174f2cf4750806551a2d2598c7d/wal-000000032 (ops 154-158)
I20260812 06:19:07.037918 22249 log.cc:1079] T 7cc6f174f2cf4750806551a2d2598c7d P 7054727a9bd7475c86c3242a1650a1bc: Deleting log segment in path: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542440112-22060-0/minicluster-data/ts-0-root/wals/7cc6f174f2cf4750806551a2d2598c7d/wal-000000033 (ops 159-163)
I20260812 06:19:07.037959 22249 log.cc:1079] T 7cc6f174f2cf4750806551a2d2598c7d P 7054727a9bd7475c86c3242a1650a1bc: Deleting log segment in path: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542440112-22060-0/minicluster-data/ts-0-root/wals/7cc6f174f2cf4750806551a2d2598c7d/wal-000000034 (ops 164-168)
I20260812 06:19:07.037983 22249 log.cc:1079] T 7cc6f174f2cf4750806551a2d2598c7d P 7054727a9bd7475c86c3242a1650a1bc: Deleting log segment in path: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542440112-22060-0/minicluster-data/ts-0-root/wals/7cc6f174f2cf4750806551a2d2598c7d/wal-000000035 (ops 169-173)
I20260812 06:19:07.038004 22249 log.cc:1079] T 7cc6f174f2cf4750806551a2d2598c7d P 7054727a9bd7475c86c3242a1650a1bc: Deleting log segment in path: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542440112-22060-0/minicluster-data/ts-0-root/wals/7cc6f174f2cf4750806551a2d2598c7d/wal-000000036 (ops 174-178)
I20260812 06:19:07.038034 22249 log.cc:1079] T 7cc6f174f2cf4750806551a2d2598c7d P 7054727a9bd7475c86c3242a1650a1bc: Deleting log segment in path: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542440112-22060-0/minicluster-data/ts-0-root/wals/7cc6f174f2cf4750806551a2d2598c7d/wal-000000037 (ops 179-183)
I20260812 06:19:07.065305 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: LogGCOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.028s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:19:07.065927 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling UndoDeltaBlockGCOp(7cc6f174f2cf4750806551a2d2598c7d): 462 bytes on disk
I20260812 06:19:07.066553 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: UndoDeltaBlockGCOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":69,"lbm_reads_lt_1ms":4}
I20260812 06:19:07.067221 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d): perf score=2.188937
I20260812 06:19:07.092489 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.025s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5926,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:07.092998 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d): perf score=2.188937
I20260812 06:19:07.107403 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.014s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5740,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:07.108012 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling MajorDeltaCompactionOp(7cc6f174f2cf4750806551a2d2598c7d): perf score=1.000000
I20260812 06:19:07.270723 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: MajorDeltaCompactionOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.163s	user 0.134s	sys 0.029s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877347,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":584,"lbm_read_time_us":13746,"lbm_reads_lt_1ms":674,"lbm_write_time_us":30985,"lbm_writes_lt_1ms":643,"mutex_wait_us":23,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":11520,"thread_start_us":75,"threads_started":1,"update_count":3000}
I20260812 06:19:07.271440 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d): perf score=14.095187
I20260812 06:19:07.325397 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.054s	user 0.043s	sys 0.008s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22393,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:07.325922 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d): perf score=2.188937
I20260812 06:19:07.341603 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.015s	user 0.005s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6072,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:07.342285 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling MajorDeltaCompactionOp(7cc6f174f2cf4750806551a2d2598c7d): perf score=1.000000
I20260812 06:19:07.417117 22060 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.708s	user 1.787s	sys 0.113s
I20260812 06:19:07.481575 22060 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.064s	user 0.009s	sys 0.000s
I20260812 06:19:07.482362 22060 tablet_server.cc:179] TabletServer@127.21.139.1:0 shutting down...
I20260812 06:19:07.483218 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: MajorDeltaCompactionOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.141s	user 0.103s	sys 0.037s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":850,"lbm_read_time_us":11523,"lbm_reads_lt_1ms":568,"lbm_write_time_us":26401,"lbm_writes_lt_1ms":543,"mutex_wait_us":425,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:19:07.483893 22354 maintenance_manager.cc:419] P 7054727a9bd7475c86c3242a1650a1bc: Scheduling FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d): perf score=6.157687
I20260812 06:19:07.508633 22249 maintenance_manager.cc:643] P 7054727a9bd7475c86c3242a1650a1bc: FlushDeltaMemStoresOp(7cc6f174f2cf4750806551a2d2598c7d) complete. Timing: real 0.024s	user 0.019s	sys 0.004s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":9080,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:19:07.509238 22060 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:07.509665 22060 tablet_replica.cc:333] T 7cc6f174f2cf4750806551a2d2598c7d P 7054727a9bd7475c86c3242a1650a1bc: stopping tablet replica
I20260812 06:19:07.509891 22060 raft_consensus.cc:2243] T 7cc6f174f2cf4750806551a2d2598c7d P 7054727a9bd7475c86c3242a1650a1bc [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:07.510115 22060 raft_consensus.cc:2272] T 7cc6f174f2cf4750806551a2d2598c7d P 7054727a9bd7475c86c3242a1650a1bc [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:07.526667 22060 tablet_server.cc:196] TabletServer@127.21.139.1:0 shutdown complete.
I20260812 06:19:07.531646 22060 master.cc:562] Master@127.21.139.62:39843 shutting down...
I20260812 06:19:07.535319 22060 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 1724d9b515ac42848e774d43196b1923 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:07.535508 22060 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 1724d9b515ac42848e774d43196b1923 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:07.535601 22060 tablet_replica.cc:333] T 00000000000000000000000000000000 P 1724d9b515ac42848e774d43196b1923: stopping tablet replica
I20260812 06:19:07.547895 22060 master.cc:584] Master@127.21.139.62:39843 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5185 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:19:07.635167 22060 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.21.139.62:37289
I20260812 06:19:07.635576 22060 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:07.637584 22407 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:07.637660 22410 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:07.637676 22412 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:07.637904 22060 server_base.cc:1061] running on GCE node
I20260812 06:19:07.638075 22060 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:07.638120 22060 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:07.638167 22060 hybrid_clock.cc:648] HybridClock initialized: now 1786515547638167 us; error 0 us; skew 500 ppm
I20260812 06:19:07.639029 22060 webserver.cc:533] Webserver started at http://127.21.139.62:40571/ using document root <none> and password file <none>
I20260812 06:19:07.639204 22060 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:07.639281 22060 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:07.639367 22060 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:07.639784 22060 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542440112-22060-0/minicluster-data/master-0-root/instance:
uuid: "947aaed375244b9597978d10115a3934"
format_stamp: "Formatted at 2026-08-12 06:19:07 on dist-test-slave-45dx"
I20260812 06:19:07.641338 22060 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:19:07.642272 22419 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:07.642541 22060 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:19:07.642609 22060 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542440112-22060-0/minicluster-data/master-0-root
uuid: "947aaed375244b9597978d10115a3934"
format_stamp: "Formatted at 2026-08-12 06:19:07 on dist-test-slave-45dx"
I20260812 06:19:07.642704 22060 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542440112-22060-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542440112-22060-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542440112-22060-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:07.654983 22060 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:07.655305 22060 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:07.659629 22060 rpc_server.cc:307] RPC server started. Bound to: 127.21.139.62:37289
I20260812 06:19:07.661100 22509 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.21.139.62:37289 every 8 connection(s)
I20260812 06:19:07.664590 22511 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:07.672290 22511 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 947aaed375244b9597978d10115a3934: Bootstrap starting.
I20260812 06:19:07.673032 22511 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 947aaed375244b9597978d10115a3934: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:07.673949 22511 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 947aaed375244b9597978d10115a3934: No bootstrap required, opened a new log
I20260812 06:19:07.674294 22511 raft_consensus.cc:359] T 00000000000000000000000000000000 P 947aaed375244b9597978d10115a3934 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "947aaed375244b9597978d10115a3934" member_type: VOTER }
I20260812 06:19:07.674376 22511 raft_consensus.cc:385] T 00000000000000000000000000000000 P 947aaed375244b9597978d10115a3934 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:07.674397 22511 raft_consensus.cc:740] T 00000000000000000000000000000000 P 947aaed375244b9597978d10115a3934 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 947aaed375244b9597978d10115a3934, State: Initialized, Role: FOLLOWER
I20260812 06:19:07.674552 22511 consensus_queue.cc:260] T 00000000000000000000000000000000 P 947aaed375244b9597978d10115a3934 [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: "947aaed375244b9597978d10115a3934" member_type: VOTER }
I20260812 06:19:07.674649 22511 raft_consensus.cc:399] T 00000000000000000000000000000000 P 947aaed375244b9597978d10115a3934 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:07.674674 22511 raft_consensus.cc:493] T 00000000000000000000000000000000 P 947aaed375244b9597978d10115a3934 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:07.674708 22511 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 947aaed375244b9597978d10115a3934 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:07.675315 22511 raft_consensus.cc:515] T 00000000000000000000000000000000 P 947aaed375244b9597978d10115a3934 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "947aaed375244b9597978d10115a3934" member_type: VOTER }
I20260812 06:19:07.675433 22511 leader_election.cc:304] T 00000000000000000000000000000000 P 947aaed375244b9597978d10115a3934 [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: 947aaed375244b9597978d10115a3934; no voters: 
I20260812 06:19:07.675575 22511 leader_election.cc:290] T 00000000000000000000000000000000 P 947aaed375244b9597978d10115a3934 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:07.675697 22515 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 947aaed375244b9597978d10115a3934 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:07.675926 22515 raft_consensus.cc:697] T 00000000000000000000000000000000 P 947aaed375244b9597978d10115a3934 [term 1 LEADER]: Becoming Leader. State: Replica: 947aaed375244b9597978d10115a3934, State: Running, Role: LEADER
I20260812 06:19:07.676069 22511 sys_catalog.cc:565] T 00000000000000000000000000000000 P 947aaed375244b9597978d10115a3934 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:07.676056 22515 consensus_queue.cc:237] T 00000000000000000000000000000000 P 947aaed375244b9597978d10115a3934 [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: "947aaed375244b9597978d10115a3934" member_type: VOTER }
I20260812 06:19:07.676554 22522 sys_catalog.cc:455] T 00000000000000000000000000000000 P 947aaed375244b9597978d10115a3934 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 947aaed375244b9597978d10115a3934. Latest consensus state: current_term: 1 leader_uuid: "947aaed375244b9597978d10115a3934" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "947aaed375244b9597978d10115a3934" member_type: VOTER } }
I20260812 06:19:07.676573 22520 sys_catalog.cc:455] T 00000000000000000000000000000000 P 947aaed375244b9597978d10115a3934 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "947aaed375244b9597978d10115a3934" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "947aaed375244b9597978d10115a3934" member_type: VOTER } }
I20260812 06:19:07.676721 22522 sys_catalog.cc:458] T 00000000000000000000000000000000 P 947aaed375244b9597978d10115a3934 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:07.676803 22520 sys_catalog.cc:458] T 00000000000000000000000000000000 P 947aaed375244b9597978d10115a3934 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:07.678022 22060 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:19:07.678460 22542 catalog_manager.cc:1594] T 00000000000000000000000000000000 P 947aaed375244b9597978d10115a3934: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:19:07.678521 22542 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:19:07.678599 22530 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:07.679209 22530 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:07.680907 22530 catalog_manager.cc:1383] Generated new cluster ID: ab44217abbb84fd7927c7a32a70e82eb
I20260812 06:19:07.680966 22530 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:07.689945 22530 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:07.690507 22530 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:07.695942 22530 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 947aaed375244b9597978d10115a3934: Generated new TSK 0
I20260812 06:19:07.696111 22530 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:07.710256 22060 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:07.712095 22545 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:07.712121 22547 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:07.712230 22550 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:07.712409 22060 server_base.cc:1061] running on GCE node
I20260812 06:19:07.712572 22060 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:07.712630 22060 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:07.712663 22060 hybrid_clock.cc:648] HybridClock initialized: now 1786515547712662 us; error 0 us; skew 500 ppm
I20260812 06:19:07.713558 22060 webserver.cc:533] Webserver started at http://127.21.139.1:34021/ using document root <none> and password file <none>
I20260812 06:19:07.713740 22060 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:07.713810 22060 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:07.713889 22060 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:07.714294 22060 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542440112-22060-0/minicluster-data/ts-0-root/instance:
uuid: "d0b4dfeb7e4f46c9a4cd4a91650d3a60"
format_stamp: "Formatted at 2026-08-12 06:19:07 on dist-test-slave-45dx"
I20260812 06:19:07.715749 22060 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:07.716737 22560 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:07.716961 22060 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.000s
I20260812 06:19:07.717053 22060 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542440112-22060-0/minicluster-data/ts-0-root
uuid: "d0b4dfeb7e4f46c9a4cd4a91650d3a60"
format_stamp: "Formatted at 2026-08-12 06:19:07 on dist-test-slave-45dx"
I20260812 06:19:07.717139 22060 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542440112-22060-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542440112-22060-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542440112-22060-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:07.726215 22060 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:07.726580 22060 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:07.726886 22060 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:07.727339 22060 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:07.727399 22060 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:07.727449 22060 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:07.727497 22060 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:07.731629 22060 rpc_server.cc:307] RPC server started. Bound to: 127.21.139.1:45895
I20260812 06:19:07.731657 22676 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.21.139.1:45895 every 8 connection(s)
I20260812 06:19:07.740007 22678 heartbeater.cc:344] Connected to a master server at 127.21.139.62:37289
I20260812 06:19:07.740105 22678 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:07.740278 22678 heartbeater.cc:507] Master 127.21.139.62:37289 requested a full tablet report, sending...
I20260812 06:19:07.740923 22440 ts_manager.cc:194] Registered new tserver with Master: d0b4dfeb7e4f46c9a4cd4a91650d3a60 (127.21.139.1:45895)
I20260812 06:19:07.741679 22440 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:57002
I20260812 06:19:07.741983 22060 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.009935645s
I20260812 06:19:07.748669 22440 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:57006:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:07.757158 22614 tablet_service.cc:1511] Processing CreateTablet for tablet b9d25d9e82ab4b01a5fe340e19d44a5a (DEFAULT_TABLE table=heavy-update-compaction-test [id=395603665347499bb911871378ef0223]), partition=
I20260812 06:19:07.757400 22614 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet b9d25d9e82ab4b01a5fe340e19d44a5a. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:07.759197 22702 tablet_bootstrap.cc:492] T b9d25d9e82ab4b01a5fe340e19d44a5a P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Bootstrap starting.
I20260812 06:19:07.760193 22702 tablet_bootstrap.cc:654] T b9d25d9e82ab4b01a5fe340e19d44a5a P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:07.761250 22702 tablet_bootstrap.cc:492] T b9d25d9e82ab4b01a5fe340e19d44a5a P d0b4dfeb7e4f46c9a4cd4a91650d3a60: No bootstrap required, opened a new log
I20260812 06:19:07.761323 22702 ts_tablet_manager.cc:1403] T b9d25d9e82ab4b01a5fe340e19d44a5a P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Time spent bootstrapping tablet: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:19:07.761682 22702 raft_consensus.cc:359] T b9d25d9e82ab4b01a5fe340e19d44a5a P d0b4dfeb7e4f46c9a4cd4a91650d3a60 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d0b4dfeb7e4f46c9a4cd4a91650d3a60" member_type: VOTER last_known_addr { host: "127.21.139.1" port: 45895 } }
I20260812 06:19:07.761778 22702 raft_consensus.cc:385] T b9d25d9e82ab4b01a5fe340e19d44a5a P d0b4dfeb7e4f46c9a4cd4a91650d3a60 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:07.761802 22702 raft_consensus.cc:740] T b9d25d9e82ab4b01a5fe340e19d44a5a P d0b4dfeb7e4f46c9a4cd4a91650d3a60 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: d0b4dfeb7e4f46c9a4cd4a91650d3a60, State: Initialized, Role: FOLLOWER
I20260812 06:19:07.761919 22702 consensus_queue.cc:260] T b9d25d9e82ab4b01a5fe340e19d44a5a P d0b4dfeb7e4f46c9a4cd4a91650d3a60 [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: "d0b4dfeb7e4f46c9a4cd4a91650d3a60" member_type: VOTER last_known_addr { host: "127.21.139.1" port: 45895 } }
I20260812 06:19:07.761982 22702 raft_consensus.cc:399] T b9d25d9e82ab4b01a5fe340e19d44a5a P d0b4dfeb7e4f46c9a4cd4a91650d3a60 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:07.762004 22702 raft_consensus.cc:493] T b9d25d9e82ab4b01a5fe340e19d44a5a P d0b4dfeb7e4f46c9a4cd4a91650d3a60 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:07.762041 22702 raft_consensus.cc:3060] T b9d25d9e82ab4b01a5fe340e19d44a5a P d0b4dfeb7e4f46c9a4cd4a91650d3a60 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:07.762951 22702 raft_consensus.cc:515] T b9d25d9e82ab4b01a5fe340e19d44a5a P d0b4dfeb7e4f46c9a4cd4a91650d3a60 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d0b4dfeb7e4f46c9a4cd4a91650d3a60" member_type: VOTER last_known_addr { host: "127.21.139.1" port: 45895 } }
I20260812 06:19:07.763084 22702 leader_election.cc:304] T b9d25d9e82ab4b01a5fe340e19d44a5a P d0b4dfeb7e4f46c9a4cd4a91650d3a60 [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: d0b4dfeb7e4f46c9a4cd4a91650d3a60; no voters: 
I20260812 06:19:07.763232 22702 leader_election.cc:290] T b9d25d9e82ab4b01a5fe340e19d44a5a P d0b4dfeb7e4f46c9a4cd4a91650d3a60 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:07.763383 22704 raft_consensus.cc:2804] T b9d25d9e82ab4b01a5fe340e19d44a5a P d0b4dfeb7e4f46c9a4cd4a91650d3a60 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:07.763605 22704 raft_consensus.cc:697] T b9d25d9e82ab4b01a5fe340e19d44a5a P d0b4dfeb7e4f46c9a4cd4a91650d3a60 [term 1 LEADER]: Becoming Leader. State: Replica: d0b4dfeb7e4f46c9a4cd4a91650d3a60, State: Running, Role: LEADER
I20260812 06:19:07.763546 22702 ts_tablet_manager.cc:1434] T b9d25d9e82ab4b01a5fe340e19d44a5a P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Time spent starting tablet: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:19:07.763553 22678 heartbeater.cc:499] Master 127.21.139.62:37289 was elected leader, sending a full tablet report...
I20260812 06:19:07.763859 22704 consensus_queue.cc:237] T b9d25d9e82ab4b01a5fe340e19d44a5a P d0b4dfeb7e4f46c9a4cd4a91650d3a60 [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: "d0b4dfeb7e4f46c9a4cd4a91650d3a60" member_type: VOTER last_known_addr { host: "127.21.139.1" port: 45895 } }
I20260812 06:19:07.765234 22440 catalog_manager.cc:5719] T b9d25d9e82ab4b01a5fe340e19d44a5a P d0b4dfeb7e4f46c9a4cd4a91650d3a60 reported cstate change: term changed from 0 to 1, leader changed from <none> to d0b4dfeb7e4f46c9a4cd4a91650d3a60 (127.21.139.1). New cstate: current_term: 1 leader_uuid: "d0b4dfeb7e4f46c9a4cd4a91650d3a60" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d0b4dfeb7e4f46c9a4cd4a91650d3a60" member_type: VOTER last_known_addr { host: "127.21.139.1" port: 45895 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:07.823439 22060 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.050s	user 0.018s	sys 0.004s
I20260812 06:19:07.982482 22681 maintenance_manager.cc:419] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Scheduling FlushMRSOp(b9d25d9e82ab4b01a5fe340e19d44a5a): perf score=19.054940
I20260812 06:19:08.162180 22571 maintenance_manager.cc:643] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: FlushMRSOp(b9d25d9e82ab4b01a5fe340e19d44a5a) complete. Timing: real 0.179s	user 0.114s	sys 0.056s Metrics: {"bytes_written":13825379,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":53,"dirs.run_cpu_time_us":207,"dirs.run_wall_time_us":848,"drs_written":1,"lbm_read_time_us":67,"lbm_reads_lt_1ms":4,"lbm_write_time_us":45499,"lbm_writes_lt_1ms":794,"mutex_wait_us":6787,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":1920,"update_count":1685}
I20260812 06:19:08.162740 22681 maintenance_manager.cc:419] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Scheduling LogGCOp(b9d25d9e82ab4b01a5fe340e19d44a5a): free 20743880 bytes of WAL
I20260812 06:19:08.162967 22571 log_reader.cc:385] T b9d25d9e82ab4b01a5fe340e19d44a5a: removed 2 log segments from log reader
I20260812 06:19:08.163017 22571 log.cc:1079] T b9d25d9e82ab4b01a5fe340e19d44a5a P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Deleting log segment in path: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542440112-22060-0/minicluster-data/ts-0-root/wals/b9d25d9e82ab4b01a5fe340e19d44a5a/wal-000000001 (ops 1-6)
I20260812 06:19:08.163046 22571 log.cc:1079] T b9d25d9e82ab4b01a5fe340e19d44a5a P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Deleting log segment in path: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542440112-22060-0/minicluster-data/ts-0-root/wals/b9d25d9e82ab4b01a5fe340e19d44a5a/wal-000000002 (ops 7-11)
I20260812 06:19:08.167888 22571 maintenance_manager.cc:643] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: LogGCOp(b9d25d9e82ab4b01a5fe340e19d44a5a) complete. Timing: real 0.005s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:19:08.168340 22681 maintenance_manager.cc:419] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Scheduling FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a): perf score=1.196750
I20260812 06:19:08.185634 22571 maintenance_manager.cc:643] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a) complete. Timing: real 0.017s	user 0.002s	sys 0.005s Metrics: {"bytes_written":2994986,"delete_count":0,"lbm_write_time_us":3195,"lbm_writes_lt_1ms":76,"reinsert_count":0,"update_count":365}
I20260812 06:19:08.186225 22681 maintenance_manager.cc:419] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Scheduling FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a): perf score=2.188937
I20260812 06:19:08.195503 22571 maintenance_manager.cc:643] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a) complete. Timing: real 0.009s	user 0.006s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3515,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:08.196014 22681 maintenance_manager.cc:419] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Scheduling UndoDeltaBlockGCOp(b9d25d9e82ab4b01a5fe340e19d44a5a): 16411393 bytes on disk
I20260812 06:19:08.196530 22571 maintenance_manager.cc:643] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: UndoDeltaBlockGCOp(b9d25d9e82ab4b01a5fe340e19d44a5a) 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:19:08.196983 22681 maintenance_manager.cc:419] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Scheduling MajorDeltaCompactionOp(b9d25d9e82ab4b01a5fe340e19d44a5a): perf score=1.000000
I20260812 06:19:08.376929 22571 maintenance_manager.cc:643] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: MajorDeltaCompactionOp(b9d25d9e82ab4b01a5fe340e19d44a5a) complete. Timing: real 0.180s	user 0.133s	sys 0.035s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774770,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":465,"lbm_read_time_us":13580,"lbm_reads_lt_1ms":569,"lbm_write_time_us":31954,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10112,"thread_start_us":310,"threads_started":5,"update_count":2500}
I20260812 06:19:08.377557 22681 maintenance_manager.cc:419] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Scheduling FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a): perf score=14.095187
I20260812 06:19:08.430837 22571 maintenance_manager.cc:643] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a) complete. Timing: real 0.053s	user 0.033s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21564,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:08.431353 22681 maintenance_manager.cc:419] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Scheduling FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a): perf score=2.188937
I20260812 06:19:08.442353 22571 maintenance_manager.cc:643] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4006,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:08.442958 22681 maintenance_manager.cc:419] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Scheduling MajorDeltaCompactionOp(b9d25d9e82ab4b01a5fe340e19d44a5a): perf score=1.000000
I20260812 06:19:08.595742 22571 maintenance_manager.cc:643] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: MajorDeltaCompactionOp(b9d25d9e82ab4b01a5fe340e19d44a5a) complete. Timing: real 0.153s	user 0.118s	sys 0.024s 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":492,"lbm_read_time_us":9863,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27798,"lbm_writes_lt_1ms":543,"mutex_wait_us":52,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":20352,"update_count":2500}
I20260812 06:19:08.596403 22681 maintenance_manager.cc:419] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Scheduling FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a): perf score=14.095187
I20260812 06:19:08.653461 22571 maintenance_manager.cc:643] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a) complete. Timing: real 0.057s	user 0.025s	sys 0.021s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21299,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:08.653946 22681 maintenance_manager.cc:419] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Scheduling FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a): perf score=2.188937
I20260812 06:19:08.663793 22571 maintenance_manager.cc:643] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3964,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:08.664188 22681 maintenance_manager.cc:419] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Scheduling MajorDeltaCompactionOp(b9d25d9e82ab4b01a5fe340e19d44a5a): perf score=1.000000
I20260812 06:19:08.849934 22571 maintenance_manager.cc:643] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: MajorDeltaCompactionOp(b9d25d9e82ab4b01a5fe340e19d44a5a) complete. Timing: real 0.186s	user 0.133s	sys 0.046s 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":255,"lbm_read_time_us":12889,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29559,"lbm_writes_lt_1ms":543,"mutex_wait_us":41,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4864,"update_count":2500}
I20260812 06:19:08.850594 22681 maintenance_manager.cc:419] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Scheduling FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a): perf score=14.095187
I20260812 06:19:08.909927 22571 maintenance_manager.cc:643] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a) complete. Timing: real 0.059s	user 0.029s	sys 0.025s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":25420,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:08.910364 22681 maintenance_manager.cc:419] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Scheduling MajorDeltaCompactionOp(b9d25d9e82ab4b01a5fe340e19d44a5a): perf score=1.000000
I20260812 06:19:09.064910 22571 maintenance_manager.cc:643] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: MajorDeltaCompactionOp(b9d25d9e82ab4b01a5fe340e19d44a5a) complete. Timing: real 0.154s	user 0.107s	sys 0.036s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672158,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":786,"lbm_read_time_us":10893,"lbm_reads_lt_1ms":463,"lbm_write_time_us":22661,"lbm_writes_lt_1ms":443,"mutex_wait_us":196,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10368,"update_count":2000}
I20260812 06:19:09.065586 22681 maintenance_manager.cc:419] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Scheduling FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a): perf score=14.095187
I20260812 06:19:09.121153 22571 maintenance_manager.cc:643] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a) complete. Timing: real 0.055s	user 0.036s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22503,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:09.121711 22681 maintenance_manager.cc:419] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Scheduling FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a): perf score=2.188937
I20260812 06:19:09.132881 22571 maintenance_manager.cc:643] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4062,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:09.133448 22681 maintenance_manager.cc:419] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Scheduling MajorDeltaCompactionOp(b9d25d9e82ab4b01a5fe340e19d44a5a): perf score=1.000000
I20260812 06:19:09.307039 22571 maintenance_manager.cc:643] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: MajorDeltaCompactionOp(b9d25d9e82ab4b01a5fe340e19d44a5a) complete. Timing: real 0.173s	user 0.122s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":790,"lbm_read_time_us":10405,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26334,"lbm_writes_lt_1ms":543,"mutex_wait_us":21,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6784,"update_count":2500}
I20260812 06:19:09.307658 22681 maintenance_manager.cc:419] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Scheduling FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a): perf score=14.095187
I20260812 06:19:09.358727 22571 maintenance_manager.cc:643] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a) complete. Timing: real 0.051s	user 0.029s	sys 0.017s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21648,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:09.359306 22681 maintenance_manager.cc:419] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Scheduling FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a): perf score=2.188937
I20260812 06:19:09.370570 22571 maintenance_manager.cc:643] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a) complete. Timing: real 0.011s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4153,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:09.371043 22681 maintenance_manager.cc:419] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Scheduling FlushMRSOp(b9d25d9e82ab4b01a5fe340e19d44a5a): perf score=1.000000
I20260812 06:19:09.396485 22571 maintenance_manager.cc:643] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: FlushMRSOp(b9d25d9e82ab4b01a5fe340e19d44a5a) complete. Timing: real 0.025s	user 0.024s	sys 0.001s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":66,"dirs.run_cpu_time_us":233,"dirs.run_wall_time_us":1367,"drs_written":1,"lbm_read_time_us":36,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1349,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:19:09.397039 22681 maintenance_manager.cc:419] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Scheduling LogGCOp(b9d25d9e82ab4b01a5fe340e19d44a5a): free 115943186 bytes of WAL
I20260812 06:19:09.397248 22571 log_reader.cc:385] T b9d25d9e82ab4b01a5fe340e19d44a5a: removed 11 log segments from log reader
I20260812 06:19:09.397308 22571 log.cc:1079] T b9d25d9e82ab4b01a5fe340e19d44a5a P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Deleting log segment in path: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542440112-22060-0/minicluster-data/ts-0-root/wals/b9d25d9e82ab4b01a5fe340e19d44a5a/wal-000000003 (ops 12-16)
I20260812 06:19:09.397360 22571 log.cc:1079] T b9d25d9e82ab4b01a5fe340e19d44a5a P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Deleting log segment in path: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542440112-22060-0/minicluster-data/ts-0-root/wals/b9d25d9e82ab4b01a5fe340e19d44a5a/wal-000000004 (ops 17-21)
I20260812 06:19:09.397418 22571 log.cc:1079] T b9d25d9e82ab4b01a5fe340e19d44a5a P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Deleting log segment in path: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542440112-22060-0/minicluster-data/ts-0-root/wals/b9d25d9e82ab4b01a5fe340e19d44a5a/wal-000000005 (ops 22-26)
I20260812 06:19:09.397459 22571 log.cc:1079] T b9d25d9e82ab4b01a5fe340e19d44a5a P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Deleting log segment in path: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542440112-22060-0/minicluster-data/ts-0-root/wals/b9d25d9e82ab4b01a5fe340e19d44a5a/wal-000000006 (ops 27-31)
I20260812 06:19:09.397497 22571 log.cc:1079] T b9d25d9e82ab4b01a5fe340e19d44a5a P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Deleting log segment in path: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542440112-22060-0/minicluster-data/ts-0-root/wals/b9d25d9e82ab4b01a5fe340e19d44a5a/wal-000000007 (ops 32-36)
I20260812 06:19:09.397539 22571 log.cc:1079] T b9d25d9e82ab4b01a5fe340e19d44a5a P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Deleting log segment in path: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542440112-22060-0/minicluster-data/ts-0-root/wals/b9d25d9e82ab4b01a5fe340e19d44a5a/wal-000000008 (ops 37-41)
I20260812 06:19:09.397575 22571 log.cc:1079] T b9d25d9e82ab4b01a5fe340e19d44a5a P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Deleting log segment in path: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542440112-22060-0/minicluster-data/ts-0-root/wals/b9d25d9e82ab4b01a5fe340e19d44a5a/wal-000000009 (ops 42-46)
I20260812 06:19:09.397612 22571 log.cc:1079] T b9d25d9e82ab4b01a5fe340e19d44a5a P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Deleting log segment in path: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542440112-22060-0/minicluster-data/ts-0-root/wals/b9d25d9e82ab4b01a5fe340e19d44a5a/wal-000000010 (ops 47-51)
I20260812 06:19:09.397650 22571 log.cc:1079] T b9d25d9e82ab4b01a5fe340e19d44a5a P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Deleting log segment in path: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542440112-22060-0/minicluster-data/ts-0-root/wals/b9d25d9e82ab4b01a5fe340e19d44a5a/wal-000000011 (ops 52-56)
I20260812 06:19:09.397686 22571 log.cc:1079] T b9d25d9e82ab4b01a5fe340e19d44a5a P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Deleting log segment in path: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542440112-22060-0/minicluster-data/ts-0-root/wals/b9d25d9e82ab4b01a5fe340e19d44a5a/wal-000000012 (ops 57-61)
I20260812 06:19:09.397722 22571 log.cc:1079] T b9d25d9e82ab4b01a5fe340e19d44a5a P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Deleting log segment in path: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542440112-22060-0/minicluster-data/ts-0-root/wals/b9d25d9e82ab4b01a5fe340e19d44a5a/wal-000000013 (ops 62-66)
I20260812 06:19:09.422475 22571 maintenance_manager.cc:643] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: LogGCOp(b9d25d9e82ab4b01a5fe340e19d44a5a) complete. Timing: real 0.025s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:19:09.428342 22681 maintenance_manager.cc:419] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Scheduling UndoDeltaBlockGCOp(b9d25d9e82ab4b01a5fe340e19d44a5a): 463 bytes on disk
I20260812 06:19:09.428911 22571 maintenance_manager.cc:643] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: UndoDeltaBlockGCOp(b9d25d9e82ab4b01a5fe340e19d44a5a) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":72,"lbm_reads_lt_1ms":4}
I20260812 06:19:09.429440 22681 maintenance_manager.cc:419] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Scheduling FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a): perf score=2.188937
I20260812 06:19:09.451361 22571 maintenance_manager.cc:643] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a) complete. Timing: real 0.022s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6559,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:09.451804 22681 maintenance_manager.cc:419] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Scheduling FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a): perf score=2.188937
I20260812 06:19:09.461664 22571 maintenance_manager.cc:643] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3955,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:09.462141 22681 maintenance_manager.cc:419] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Scheduling MajorDeltaCompactionOp(b9d25d9e82ab4b01a5fe340e19d44a5a): perf score=1.000000
I20260812 06:19:09.701829 22571 maintenance_manager.cc:643] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: MajorDeltaCompactionOp(b9d25d9e82ab4b01a5fe340e19d44a5a) complete. Timing: real 0.240s	user 0.141s	sys 0.093s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979749,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":662,"lbm_read_time_us":15936,"lbm_reads_lt_1ms":774,"lbm_write_time_us":36021,"lbm_writes_lt_1ms":743,"mutex_wait_us":20,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":14080,"thread_start_us":110,"threads_started":1,"update_count":3500}
I20260812 06:19:09.702600 22681 maintenance_manager.cc:419] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Scheduling FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a): perf score=18.063937
I20260812 06:19:09.772436 22571 maintenance_manager.cc:643] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a) complete. Timing: real 0.070s	user 0.029s	sys 0.031s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":27093,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:09.772940 22681 maintenance_manager.cc:419] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Scheduling FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a): perf score=2.188937
I20260812 06:19:09.783461 22571 maintenance_manager.cc:643] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4214,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:09.784036 22681 maintenance_manager.cc:419] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Scheduling MajorDeltaCompactionOp(b9d25d9e82ab4b01a5fe340e19d44a5a): perf score=1.000000
I20260812 06:19:09.983644 22571 maintenance_manager.cc:643] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: MajorDeltaCompactionOp(b9d25d9e82ab4b01a5fe340e19d44a5a) complete. Timing: real 0.199s	user 0.123s	sys 0.076s 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":656,"lbm_read_time_us":13601,"lbm_reads_lt_1ms":672,"lbm_write_time_us":32591,"lbm_writes_lt_1ms":643,"mutex_wait_us":389,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":48000,"update_count":3000}
I20260812 06:19:09.984460 22681 maintenance_manager.cc:419] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Scheduling FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a): perf score=14.095187
I20260812 06:19:10.029702 22571 maintenance_manager.cc:643] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a) complete. Timing: real 0.045s	user 0.027s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20164,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:10.030375 22681 maintenance_manager.cc:419] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Scheduling FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a): perf score=2.188937
I20260812 06:19:10.047290 22571 maintenance_manager.cc:643] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a) complete. Timing: real 0.017s	user 0.011s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6821,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:10.047835 22681 maintenance_manager.cc:419] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Scheduling MajorDeltaCompactionOp(b9d25d9e82ab4b01a5fe340e19d44a5a): perf score=1.000000
I20260812 06:19:10.208392 22571 maintenance_manager.cc:643] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: MajorDeltaCompactionOp(b9d25d9e82ab4b01a5fe340e19d44a5a) complete. Timing: real 0.160s	user 0.102s	sys 0.058s 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":545,"lbm_read_time_us":12853,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27008,"lbm_writes_lt_1ms":543,"mutex_wait_us":269,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13952,"update_count":2500}
I20260812 06:19:10.209085 22681 maintenance_manager.cc:419] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Scheduling FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a): perf score=14.095187
I20260812 06:19:10.257077 22571 maintenance_manager.cc:643] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a) complete. Timing: real 0.048s	user 0.019s	sys 0.028s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21244,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:10.257683 22681 maintenance_manager.cc:419] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Scheduling FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a): perf score=2.188937
I20260812 06:19:10.274504 22571 maintenance_manager.cc:643] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a) complete. Timing: real 0.017s	user 0.006s	sys 0.009s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6695,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:10.275029 22681 maintenance_manager.cc:419] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Scheduling MajorDeltaCompactionOp(b9d25d9e82ab4b01a5fe340e19d44a5a): perf score=1.000000
I20260812 06:19:10.447633 22571 maintenance_manager.cc:643] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: MajorDeltaCompactionOp(b9d25d9e82ab4b01a5fe340e19d44a5a) complete. Timing: real 0.172s	user 0.086s	sys 0.081s 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":188,"lbm_read_time_us":11304,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28564,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":60160,"update_count":2500}
I20260812 06:19:10.448269 22681 maintenance_manager.cc:419] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Scheduling FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a): perf score=14.095187
I20260812 06:19:10.504545 22571 maintenance_manager.cc:643] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a) complete. Timing: real 0.056s	user 0.028s	sys 0.028s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19626,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:10.505057 22681 maintenance_manager.cc:419] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Scheduling FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a): perf score=2.188937
I20260812 06:19:10.515045 22571 maintenance_manager.cc:643] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4180,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:10.515470 22681 maintenance_manager.cc:419] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Scheduling MajorDeltaCompactionOp(b9d25d9e82ab4b01a5fe340e19d44a5a): perf score=1.000000
I20260812 06:19:10.685209 22571 maintenance_manager.cc:643] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: MajorDeltaCompactionOp(b9d25d9e82ab4b01a5fe340e19d44a5a) complete. Timing: real 0.170s	user 0.113s	sys 0.051s 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":923,"lbm_read_time_us":11669,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26858,"lbm_writes_lt_1ms":543,"mutex_wait_us":241,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4864,"update_count":2500}
I20260812 06:19:10.685956 22681 maintenance_manager.cc:419] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Scheduling FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a): perf score=14.095187
I20260812 06:19:10.748939 22571 maintenance_manager.cc:643] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a) complete. Timing: real 0.063s	user 0.037s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23407,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:10.749495 22681 maintenance_manager.cc:419] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Scheduling FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a): perf score=2.188937
I20260812 06:19:10.760067 22571 maintenance_manager.cc:643] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4097,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:10.760515 22681 maintenance_manager.cc:419] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Scheduling FlushMRSOp(b9d25d9e82ab4b01a5fe340e19d44a5a): perf score=1.000000
I20260812 06:19:10.805599 22571 maintenance_manager.cc:643] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: FlushMRSOp(b9d25d9e82ab4b01a5fe340e19d44a5a) complete. Timing: real 0.045s	user 0.027s	sys 0.005s Metrics: {"bytes_written":1152514,"cfile_init":1,"dirs.queue_time_us":61,"dirs.run_cpu_time_us":227,"dirs.run_wall_time_us":1401,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1495,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:10.806278 22681 maintenance_manager.cc:419] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Scheduling LogGCOp(b9d25d9e82ab4b01a5fe340e19d44a5a): free 121006432 bytes of WAL
I20260812 06:19:10.806514 22571 log_reader.cc:385] T b9d25d9e82ab4b01a5fe340e19d44a5a: removed 12 log segments from log reader
I20260812 06:19:10.806561 22571 log.cc:1079] T b9d25d9e82ab4b01a5fe340e19d44a5a P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Deleting log segment in path: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542440112-22060-0/minicluster-data/ts-0-root/wals/b9d25d9e82ab4b01a5fe340e19d44a5a/wal-000000014 (ops 67-71)
I20260812 06:19:10.806589 22571 log.cc:1079] T b9d25d9e82ab4b01a5fe340e19d44a5a P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Deleting log segment in path: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542440112-22060-0/minicluster-data/ts-0-root/wals/b9d25d9e82ab4b01a5fe340e19d44a5a/wal-000000015 (ops 72-76)
I20260812 06:19:10.806648 22571 log.cc:1079] T b9d25d9e82ab4b01a5fe340e19d44a5a P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Deleting log segment in path: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542440112-22060-0/minicluster-data/ts-0-root/wals/b9d25d9e82ab4b01a5fe340e19d44a5a/wal-000000016 (ops 77-81)
I20260812 06:19:10.806705 22571 log.cc:1079] T b9d25d9e82ab4b01a5fe340e19d44a5a P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Deleting log segment in path: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542440112-22060-0/minicluster-data/ts-0-root/wals/b9d25d9e82ab4b01a5fe340e19d44a5a/wal-000000017 (ops 82-86)
I20260812 06:19:10.806751 22571 log.cc:1079] T b9d25d9e82ab4b01a5fe340e19d44a5a P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Deleting log segment in path: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542440112-22060-0/minicluster-data/ts-0-root/wals/b9d25d9e82ab4b01a5fe340e19d44a5a/wal-000000018 (ops 87-91)
I20260812 06:19:10.806795 22571 log.cc:1079] T b9d25d9e82ab4b01a5fe340e19d44a5a P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Deleting log segment in path: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542440112-22060-0/minicluster-data/ts-0-root/wals/b9d25d9e82ab4b01a5fe340e19d44a5a/wal-000000019 (ops 92-96)
I20260812 06:19:10.806840 22571 log.cc:1079] T b9d25d9e82ab4b01a5fe340e19d44a5a P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Deleting log segment in path: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542440112-22060-0/minicluster-data/ts-0-root/wals/b9d25d9e82ab4b01a5fe340e19d44a5a/wal-000000020 (ops 97-101)
I20260812 06:19:10.806881 22571 log.cc:1079] T b9d25d9e82ab4b01a5fe340e19d44a5a P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Deleting log segment in path: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542440112-22060-0/minicluster-data/ts-0-root/wals/b9d25d9e82ab4b01a5fe340e19d44a5a/wal-000000021 (ops 102-106)
I20260812 06:19:10.806923 22571 log.cc:1079] T b9d25d9e82ab4b01a5fe340e19d44a5a P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Deleting log segment in path: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542440112-22060-0/minicluster-data/ts-0-root/wals/b9d25d9e82ab4b01a5fe340e19d44a5a/wal-000000022 (ops 107-110)
I20260812 06:19:10.806964 22571 log.cc:1079] T b9d25d9e82ab4b01a5fe340e19d44a5a P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Deleting log segment in path: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542440112-22060-0/minicluster-data/ts-0-root/wals/b9d25d9e82ab4b01a5fe340e19d44a5a/wal-000000023 (ops 111-115)
I20260812 06:19:10.807001 22571 log.cc:1079] T b9d25d9e82ab4b01a5fe340e19d44a5a P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Deleting log segment in path: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542440112-22060-0/minicluster-data/ts-0-root/wals/b9d25d9e82ab4b01a5fe340e19d44a5a/wal-000000024 (ops 116-120)
I20260812 06:19:10.807044 22571 log.cc:1079] T b9d25d9e82ab4b01a5fe340e19d44a5a P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Deleting log segment in path: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542440112-22060-0/minicluster-data/ts-0-root/wals/b9d25d9e82ab4b01a5fe340e19d44a5a/wal-000000025 (ops 121-125)
I20260812 06:19:10.833053 22571 maintenance_manager.cc:643] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: LogGCOp(b9d25d9e82ab4b01a5fe340e19d44a5a) complete. Timing: real 0.027s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:19:10.833539 22681 maintenance_manager.cc:419] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Scheduling FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a): perf score=2.188937
I20260812 06:19:10.850497 22571 maintenance_manager.cc:643] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a) complete. Timing: real 0.017s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4791,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:10.850916 22681 maintenance_manager.cc:419] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Scheduling UndoDeltaBlockGCOp(b9d25d9e82ab4b01a5fe340e19d44a5a): 447 bytes on disk
I20260812 06:19:10.851290 22571 maintenance_manager.cc:643] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: UndoDeltaBlockGCOp(b9d25d9e82ab4b01a5fe340e19d44a5a) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4}
I20260812 06:19:10.851783 22681 maintenance_manager.cc:419] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Scheduling FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a): perf score=2.188937
I20260812 06:19:10.861820 22571 maintenance_manager.cc:643] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3871,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:10.862299 22681 maintenance_manager.cc:419] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Scheduling MajorDeltaCompactionOp(b9d25d9e82ab4b01a5fe340e19d44a5a): perf score=1.000000
I20260812 06:19:11.098191 22571 maintenance_manager.cc:643] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: MajorDeltaCompactionOp(b9d25d9e82ab4b01a5fe340e19d44a5a) complete. Timing: real 0.236s	user 0.148s	sys 0.079s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979750,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":515,"lbm_read_time_us":15925,"lbm_reads_lt_1ms":774,"lbm_write_time_us":37040,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":3200,"thread_start_us":78,"threads_started":1,"update_count":3500}
I20260812 06:19:11.098960 22681 maintenance_manager.cc:419] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Scheduling FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a): perf score=18.063937
I20260812 06:19:11.165745 22571 maintenance_manager.cc:643] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a) complete. Timing: real 0.067s	user 0.035s	sys 0.020s Metrics: {"bytes_written":20512314,"delete_count":0,"lbm_write_time_us":25590,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:11.166189 22681 maintenance_manager.cc:419] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Scheduling FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a): perf score=2.188937
I20260812 06:19:11.177989 22571 maintenance_manager.cc:643] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4136,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:11.178470 22681 maintenance_manager.cc:419] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Scheduling MajorDeltaCompactionOp(b9d25d9e82ab4b01a5fe340e19d44a5a): perf score=1.000000
I20260812 06:19:11.381623 22571 maintenance_manager.cc:643] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: MajorDeltaCompactionOp(b9d25d9e82ab4b01a5fe340e19d44a5a) complete. Timing: real 0.203s	user 0.143s	sys 0.059s 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":537,"lbm_read_time_us":13838,"lbm_reads_lt_1ms":672,"lbm_write_time_us":32803,"lbm_writes_lt_1ms":643,"mutex_wait_us":275,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":11136,"update_count":3000}
I20260812 06:19:11.382241 22681 maintenance_manager.cc:419] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Scheduling FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a): perf score=14.095187
I20260812 06:19:11.431018 22571 maintenance_manager.cc:643] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a) complete. Timing: real 0.049s	user 0.038s	sys 0.008s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21079,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:11.431634 22681 maintenance_manager.cc:419] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Scheduling FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a): perf score=2.188937
I20260812 06:19:11.455981 22571 maintenance_manager.cc:643] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a) complete. Timing: real 0.024s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5676,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:11.456521 22681 maintenance_manager.cc:419] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Scheduling FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a): perf score=2.188937
I20260812 06:19:11.466434 22571 maintenance_manager.cc:643] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3947,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:11.466930 22681 maintenance_manager.cc:419] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Scheduling MajorDeltaCompactionOp(b9d25d9e82ab4b01a5fe340e19d44a5a): perf score=1.000000
I20260812 06:19:11.664527 22571 maintenance_manager.cc:643] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: MajorDeltaCompactionOp(b9d25d9e82ab4b01a5fe340e19d44a5a) complete. Timing: real 0.197s	user 0.133s	sys 0.064s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877219,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1250,"lbm_read_time_us":12591,"lbm_reads_lt_1ms":673,"lbm_write_time_us":34156,"lbm_writes_lt_1ms":643,"mutex_wait_us":352,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":11136,"update_count":3000}
I20260812 06:19:11.665167 22681 maintenance_manager.cc:419] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Scheduling FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a): perf score=14.095187
I20260812 06:19:11.708246 22571 maintenance_manager.cc:643] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a) complete. Timing: real 0.043s	user 0.025s	sys 0.013s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18540,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:11.708918 22681 maintenance_manager.cc:419] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Scheduling FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a): perf score=3.181125
I20260812 06:19:11.732275 22571 maintenance_manager.cc:643] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a) complete. Timing: real 0.023s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":6114,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:11.732801 22681 maintenance_manager.cc:419] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Scheduling FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a): perf score=2.188937
I20260812 06:19:11.742110 22571 maintenance_manager.cc:643] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a) complete. Timing: real 0.009s	user 0.003s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3714,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:11.742657 22681 maintenance_manager.cc:419] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Scheduling MajorDeltaCompactionOp(b9d25d9e82ab4b01a5fe340e19d44a5a): perf score=1.000000
I20260812 06:19:11.949628 22571 maintenance_manager.cc:643] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: MajorDeltaCompactionOp(b9d25d9e82ab4b01a5fe340e19d44a5a) complete. Timing: real 0.207s	user 0.135s	sys 0.071s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877207,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":653,"lbm_read_time_us":14260,"lbm_reads_lt_1ms":673,"lbm_write_time_us":34380,"lbm_writes_lt_1ms":643,"mutex_wait_us":81,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":11904,"update_count":3000}
I20260812 06:19:11.950423 22681 maintenance_manager.cc:419] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Scheduling FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a): perf score=14.095187
I20260812 06:19:12.013288 22571 maintenance_manager.cc:643] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a) complete. Timing: real 0.063s	user 0.039s	sys 0.008s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21536,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:12.013902 22681 maintenance_manager.cc:419] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Scheduling FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a): perf score=2.188937
I20260812 06:19:12.024467 22571 maintenance_manager.cc:643] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a) complete. Timing: real 0.010s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4210,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:12.025241 22681 maintenance_manager.cc:419] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Scheduling MajorDeltaCompactionOp(b9d25d9e82ab4b01a5fe340e19d44a5a): perf score=1.000000
I20260812 06:19:12.194531 22571 maintenance_manager.cc:643] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: MajorDeltaCompactionOp(b9d25d9e82ab4b01a5fe340e19d44a5a) complete. Timing: real 0.169s	user 0.121s	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":929,"lbm_read_time_us":12520,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28572,"lbm_writes_lt_1ms":543,"mutex_wait_us":296,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":16640,"update_count":2500}
I20260812 06:19:12.195250 22681 maintenance_manager.cc:419] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Scheduling FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a): perf score=14.095187
I20260812 06:19:12.251899 22571 maintenance_manager.cc:643] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a) complete. Timing: real 0.056s	user 0.035s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22686,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:12.252549 22681 maintenance_manager.cc:419] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Scheduling FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a): perf score=2.188937
I20260812 06:19:12.263573 22571 maintenance_manager.cc:643] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a) complete. Timing: real 0.011s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4033,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:12.264225 22681 maintenance_manager.cc:419] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Scheduling FlushMRSOp(b9d25d9e82ab4b01a5fe340e19d44a5a): perf score=1.000000
I20260812 06:19:12.303591 22571 maintenance_manager.cc:643] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: FlushMRSOp(b9d25d9e82ab4b01a5fe340e19d44a5a) complete. Timing: real 0.039s	user 0.029s	sys 0.002s Metrics: {"bytes_written":1234475,"cfile_init":1,"dirs.queue_time_us":79,"dirs.run_cpu_time_us":193,"dirs.run_wall_time_us":1420,"drs_written":1,"lbm_read_time_us":36,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1553,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:12.304296 22681 maintenance_manager.cc:419] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Scheduling LogGCOp(b9d25d9e82ab4b01a5fe340e19d44a5a): free 124710498 bytes of WAL
I20260812 06:19:12.304594 22571 log_reader.cc:385] T b9d25d9e82ab4b01a5fe340e19d44a5a: removed 12 log segments from log reader
I20260812 06:19:12.304641 22571 log.cc:1079] T b9d25d9e82ab4b01a5fe340e19d44a5a P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Deleting log segment in path: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542440112-22060-0/minicluster-data/ts-0-root/wals/b9d25d9e82ab4b01a5fe340e19d44a5a/wal-000000026 (ops 126-130)
I20260812 06:19:12.304669 22571 log.cc:1079] T b9d25d9e82ab4b01a5fe340e19d44a5a P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Deleting log segment in path: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542440112-22060-0/minicluster-data/ts-0-root/wals/b9d25d9e82ab4b01a5fe340e19d44a5a/wal-000000027 (ops 131-134)
I20260812 06:19:12.304729 22571 log.cc:1079] T b9d25d9e82ab4b01a5fe340e19d44a5a P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Deleting log segment in path: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542440112-22060-0/minicluster-data/ts-0-root/wals/b9d25d9e82ab4b01a5fe340e19d44a5a/wal-000000028 (ops 135-139)
I20260812 06:19:12.304773 22571 log.cc:1079] T b9d25d9e82ab4b01a5fe340e19d44a5a P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Deleting log segment in path: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542440112-22060-0/minicluster-data/ts-0-root/wals/b9d25d9e82ab4b01a5fe340e19d44a5a/wal-000000029 (ops 140-144)
I20260812 06:19:12.304813 22571 log.cc:1079] T b9d25d9e82ab4b01a5fe340e19d44a5a P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Deleting log segment in path: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542440112-22060-0/minicluster-data/ts-0-root/wals/b9d25d9e82ab4b01a5fe340e19d44a5a/wal-000000030 (ops 145-149)
I20260812 06:19:12.304854 22571 log.cc:1079] T b9d25d9e82ab4b01a5fe340e19d44a5a P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Deleting log segment in path: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542440112-22060-0/minicluster-data/ts-0-root/wals/b9d25d9e82ab4b01a5fe340e19d44a5a/wal-000000031 (ops 150-154)
I20260812 06:19:12.304899 22571 log.cc:1079] T b9d25d9e82ab4b01a5fe340e19d44a5a P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Deleting log segment in path: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542440112-22060-0/minicluster-data/ts-0-root/wals/b9d25d9e82ab4b01a5fe340e19d44a5a/wal-000000032 (ops 155-159)
I20260812 06:19:12.304945 22571 log.cc:1079] T b9d25d9e82ab4b01a5fe340e19d44a5a P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Deleting log segment in path: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542440112-22060-0/minicluster-data/ts-0-root/wals/b9d25d9e82ab4b01a5fe340e19d44a5a/wal-000000033 (ops 160-164)
I20260812 06:19:12.304986 22571 log.cc:1079] T b9d25d9e82ab4b01a5fe340e19d44a5a P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Deleting log segment in path: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542440112-22060-0/minicluster-data/ts-0-root/wals/b9d25d9e82ab4b01a5fe340e19d44a5a/wal-000000034 (ops 165-169)
I20260812 06:19:12.305024 22571 log.cc:1079] T b9d25d9e82ab4b01a5fe340e19d44a5a P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Deleting log segment in path: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542440112-22060-0/minicluster-data/ts-0-root/wals/b9d25d9e82ab4b01a5fe340e19d44a5a/wal-000000035 (ops 170-175)
I20260812 06:19:12.305068 22571 log.cc:1079] T b9d25d9e82ab4b01a5fe340e19d44a5a P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Deleting log segment in path: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542440112-22060-0/minicluster-data/ts-0-root/wals/b9d25d9e82ab4b01a5fe340e19d44a5a/wal-000000036 (ops 176-180)
I20260812 06:19:12.305110 22571 log.cc:1079] T b9d25d9e82ab4b01a5fe340e19d44a5a P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Deleting log segment in path: /tmp/dist-test-taskR3Jo5H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542440112-22060-0/minicluster-data/ts-0-root/wals/b9d25d9e82ab4b01a5fe340e19d44a5a/wal-000000037 (ops 181-185)
I20260812 06:19:12.329751 22571 maintenance_manager.cc:643] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: LogGCOp(b9d25d9e82ab4b01a5fe340e19d44a5a) complete. Timing: real 0.025s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:19:12.330160 22681 maintenance_manager.cc:419] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Scheduling UndoDeltaBlockGCOp(b9d25d9e82ab4b01a5fe340e19d44a5a): 473 bytes on disk
I20260812 06:19:12.330605 22571 maintenance_manager.cc:643] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: UndoDeltaBlockGCOp(b9d25d9e82ab4b01a5fe340e19d44a5a) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4}
I20260812 06:19:12.331141 22681 maintenance_manager.cc:419] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Scheduling FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a): perf score=2.188937
I20260812 06:19:12.349736 22571 maintenance_manager.cc:643] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a) complete. Timing: real 0.018s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4209,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:12.350245 22681 maintenance_manager.cc:419] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Scheduling FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a): perf score=2.188937
I20260812 06:19:12.360244 22571 maintenance_manager.cc:643] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a) complete. Timing: real 0.010s	user 0.005s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3989,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:12.360852 22681 maintenance_manager.cc:419] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Scheduling MajorDeltaCompactionOp(b9d25d9e82ab4b01a5fe340e19d44a5a): perf score=1.000000
I20260812 06:19:12.580449 22571 maintenance_manager.cc:643] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: MajorDeltaCompactionOp(b9d25d9e82ab4b01a5fe340e19d44a5a) complete. Timing: real 0.219s	user 0.139s	sys 0.076s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979749,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1235,"lbm_read_time_us":15572,"lbm_reads_lt_1ms":774,"lbm_write_time_us":40115,"lbm_writes_lt_1ms":743,"mutex_wait_us":18,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":18048,"thread_start_us":78,"threads_started":1,"update_count":3500}
I20260812 06:19:12.581000 22681 maintenance_manager.cc:419] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Scheduling FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a): perf score=18.063937
I20260812 06:19:12.645018 22571 maintenance_manager.cc:643] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a) complete. Timing: real 0.064s	user 0.048s	sys 0.015s Metrics: {"bytes_written":20512320,"delete_count":0,"lbm_write_time_us":29086,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:12.645551 22681 maintenance_manager.cc:419] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Scheduling FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a): perf score=2.188937
I20260812 06:19:12.656450 22571 maintenance_manager.cc:643] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: FlushDeltaMemStoresOp(b9d25d9e82ab4b01a5fe340e19d44a5a) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3853,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:12.656937 22681 maintenance_manager.cc:419] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: Scheduling MajorDeltaCompactionOp(b9d25d9e82ab4b01a5fe340e19d44a5a): perf score=1.000000
I20260812 06:19:12.686754 22060 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.863s	user 1.743s	sys 0.224s
I20260812 06:19:12.739032 22060 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.052s	user 0.001s	sys 0.000s
I20260812 06:19:12.739534 22060 tablet_server.cc:179] TabletServer@127.21.139.1:0 shutting down...
I20260812 06:19:12.808506 22571 maintenance_manager.cc:643] P d0b4dfeb7e4f46c9a4cd4a91650d3a60: MajorDeltaCompactionOp(b9d25d9e82ab4b01a5fe340e19d44a5a) complete. Timing: real 0.151s	user 0.100s	sys 0.051s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877107,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":404,"lbm_read_time_us":13011,"lbm_reads_lt_1ms":668,"lbm_write_time_us":28486,"lbm_writes_lt_1ms":643,"mutex_wait_us":35,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":3000}
I20260812 06:19:12.809243 22060 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:12.809566 22060 tablet_replica.cc:333] T b9d25d9e82ab4b01a5fe340e19d44a5a P d0b4dfeb7e4f46c9a4cd4a91650d3a60: stopping tablet replica
I20260812 06:19:12.809733 22060 raft_consensus.cc:2243] T b9d25d9e82ab4b01a5fe340e19d44a5a P d0b4dfeb7e4f46c9a4cd4a91650d3a60 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:12.809919 22060 raft_consensus.cc:2272] T b9d25d9e82ab4b01a5fe340e19d44a5a P d0b4dfeb7e4f46c9a4cd4a91650d3a60 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:12.824996 22060 tablet_server.cc:196] TabletServer@127.21.139.1:0 shutdown complete.
I20260812 06:19:12.868616 22060 master.cc:562] Master@127.21.139.62:37289 shutting down...
I20260812 06:19:12.871730 22060 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 947aaed375244b9597978d10115a3934 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:12.871887 22060 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 947aaed375244b9597978d10115a3934 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:12.871937 22060 tablet_replica.cc:333] T 00000000000000000000000000000000 P 947aaed375244b9597978d10115a3934: stopping tablet replica
I20260812 06:19:12.884215 22060 master.cc:584] Master@127.21.139.62:37289 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5337 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10523 ms total)

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