[==========] 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:16:24.027096 19331 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.18.224.254:42071
I20260812 06:16:24.028189 19331 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:16:24.028801 19331 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:24.035478 19342 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:16:24.035532 19338 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:16:24.035627 19331 server_base.cc:1061] running on GCE node
W20260812 06:16:24.035889 19339 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:16:24.036459 19331 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:24.036583 19331 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:16:24.036631 19331 hybrid_clock.cc:648] HybridClock initialized: now 1786515384036629 us; error 0 us; skew 500 ppm
I20260812 06:16:24.038669 19331 webserver.cc:533] Webserver started at http://127.18.224.254:37377/ using document root <none> and password file <none>
I20260812 06:16:24.039258 19331 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:24.039350 19331 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:24.039629 19331 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:24.041333 19331 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384016249-19331-0/minicluster-data/master-0-root/instance:
uuid: "1399a77633fe4b3c846801175eb2f21a"
format_stamp: "Formatted at 2026-08-12 06:16:24 on dist-test-slave-5l3k"
I20260812 06:16:24.044987 19331 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.005s	sys 0.000s
I20260812 06:16:24.047242 19350 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:16:24.048316 19331 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:16:24.048458 19331 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384016249-19331-0/minicluster-data/master-0-root
uuid: "1399a77633fe4b3c846801175eb2f21a"
format_stamp: "Formatted at 2026-08-12 06:16:24 on dist-test-slave-5l3k"
I20260812 06:16:24.048570 19331 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384016249-19331-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384016249-19331-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384016249-19331-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:16:24.065194 19331 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:24.065917 19331 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:16:24.066123 19331 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:24.074514 19331 rpc_server.cc:307] RPC server started. Bound to: 127.18.224.254:42071
I20260812 06:16:24.074551 19409 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.18.224.254:42071 every 8 connection(s)
I20260812 06:16:24.077023 19410 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:16:24.082849 19410 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 1399a77633fe4b3c846801175eb2f21a: Bootstrap starting.
I20260812 06:16:24.085316 19410 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 1399a77633fe4b3c846801175eb2f21a: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:24.086282 19410 log.cc:826] T 00000000000000000000000000000000 P 1399a77633fe4b3c846801175eb2f21a: Log is configured to *not* fsync() on all Append() calls
I20260812 06:16:24.088272 19410 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 1399a77633fe4b3c846801175eb2f21a: No bootstrap required, opened a new log
I20260812 06:16:24.091360 19410 raft_consensus.cc:359] T 00000000000000000000000000000000 P 1399a77633fe4b3c846801175eb2f21a [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1399a77633fe4b3c846801175eb2f21a" member_type: VOTER }
I20260812 06:16:24.091540 19410 raft_consensus.cc:385] T 00000000000000000000000000000000 P 1399a77633fe4b3c846801175eb2f21a [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:24.091665 19410 raft_consensus.cc:740] T 00000000000000000000000000000000 P 1399a77633fe4b3c846801175eb2f21a [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 1399a77633fe4b3c846801175eb2f21a, State: Initialized, Role: FOLLOWER
I20260812 06:16:24.092331 19410 consensus_queue.cc:260] T 00000000000000000000000000000000 P 1399a77633fe4b3c846801175eb2f21a [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: "1399a77633fe4b3c846801175eb2f21a" member_type: VOTER }
I20260812 06:16:24.092501 19410 raft_consensus.cc:399] T 00000000000000000000000000000000 P 1399a77633fe4b3c846801175eb2f21a [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:24.092599 19410 raft_consensus.cc:493] T 00000000000000000000000000000000 P 1399a77633fe4b3c846801175eb2f21a [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:24.092760 19410 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 1399a77633fe4b3c846801175eb2f21a [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:24.093637 19410 raft_consensus.cc:515] T 00000000000000000000000000000000 P 1399a77633fe4b3c846801175eb2f21a [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1399a77633fe4b3c846801175eb2f21a" member_type: VOTER }
I20260812 06:16:24.094117 19410 leader_election.cc:304] T 00000000000000000000000000000000 P 1399a77633fe4b3c846801175eb2f21a [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: 1399a77633fe4b3c846801175eb2f21a; no voters: 
I20260812 06:16:24.094520 19410 leader_election.cc:290] T 00000000000000000000000000000000 P 1399a77633fe4b3c846801175eb2f21a [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:24.094745 19413 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 1399a77633fe4b3c846801175eb2f21a [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:24.095036 19413 raft_consensus.cc:697] T 00000000000000000000000000000000 P 1399a77633fe4b3c846801175eb2f21a [term 1 LEADER]: Becoming Leader. State: Replica: 1399a77633fe4b3c846801175eb2f21a, State: Running, Role: LEADER
I20260812 06:16:24.095427 19413 consensus_queue.cc:237] T 00000000000000000000000000000000 P 1399a77633fe4b3c846801175eb2f21a [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: "1399a77633fe4b3c846801175eb2f21a" member_type: VOTER }
I20260812 06:16:24.095610 19410 sys_catalog.cc:565] T 00000000000000000000000000000000 P 1399a77633fe4b3c846801175eb2f21a [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:24.097522 19415 sys_catalog.cc:455] T 00000000000000000000000000000000 P 1399a77633fe4b3c846801175eb2f21a [sys.catalog]: SysCatalogTable state changed. Reason: New leader 1399a77633fe4b3c846801175eb2f21a. Latest consensus state: current_term: 1 leader_uuid: "1399a77633fe4b3c846801175eb2f21a" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1399a77633fe4b3c846801175eb2f21a" member_type: VOTER } }
I20260812 06:16:24.097470 19414 sys_catalog.cc:455] T 00000000000000000000000000000000 P 1399a77633fe4b3c846801175eb2f21a [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "1399a77633fe4b3c846801175eb2f21a" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1399a77633fe4b3c846801175eb2f21a" member_type: VOTER } }
I20260812 06:16:24.097608 19415 sys_catalog.cc:458] T 00000000000000000000000000000000 P 1399a77633fe4b3c846801175eb2f21a [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:24.097608 19414 sys_catalog.cc:458] T 00000000000000000000000000000000 P 1399a77633fe4b3c846801175eb2f21a [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:24.097970 19331 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:24.098052 19431 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:24.100410 19431 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:24.105070 19431 catalog_manager.cc:1383] Generated new cluster ID: 39dcbc83ae074e4b9ac336c143b1ad0a
I20260812 06:16:24.105155 19431 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:24.130156 19431 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:24.131155 19431 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:24.140733 19431 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 1399a77633fe4b3c846801175eb2f21a: Generated new TSK 0
I20260812 06:16:24.141443 19431 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:24.162961 19331 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:24.165846 19438 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:16:24.165891 19437 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:16:24.166145 19331 server_base.cc:1061] running on GCE node
W20260812 06:16:24.166210 19440 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:16:24.166415 19331 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:24.166481 19331 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:16:24.166548 19331 hybrid_clock.cc:648] HybridClock initialized: now 1786515384166546 us; error 0 us; skew 500 ppm
I20260812 06:16:24.167598 19331 webserver.cc:533] Webserver started at http://127.18.224.193:46343/ using document root <none> and password file <none>
I20260812 06:16:24.167779 19331 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:24.167855 19331 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:24.167938 19331 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:24.168354 19331 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384016249-19331-0/minicluster-data/ts-0-root/instance:
uuid: "dabbb03c8b614e029041f01f3b6adcaa"
format_stamp: "Formatted at 2026-08-12 06:16:24 on dist-test-slave-5l3k"
I20260812 06:16:24.169955 19331 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:16:24.171062 19445 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:16:24.171316 19331 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.000s
I20260812 06:16:24.171394 19331 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384016249-19331-0/minicluster-data/ts-0-root
uuid: "dabbb03c8b614e029041f01f3b6adcaa"
format_stamp: "Formatted at 2026-08-12 06:16:24 on dist-test-slave-5l3k"
I20260812 06:16:24.171492 19331 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384016249-19331-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384016249-19331-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384016249-19331-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:16:24.201187 19331 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:24.201711 19331 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:24.202260 19331 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:24.203258 19331 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:24.203315 19331 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:24.203362 19331 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:24.203377 19331 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:24.216425 19331 rpc_server.cc:307] RPC server started. Bound to: 127.18.224.193:43579
I20260812 06:16:24.216450 19518 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.18.224.193:43579 every 8 connection(s)
I20260812 06:16:24.234582 19519 heartbeater.cc:344] Connected to a master server at 127.18.224.254:42071
I20260812 06:16:24.234906 19519 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:24.235558 19519 heartbeater.cc:507] Master 127.18.224.254:42071 requested a full tablet report, sending...
I20260812 06:16:24.237486 19369 ts_manager.cc:194] Registered new tserver with Master: dabbb03c8b614e029041f01f3b6adcaa (127.18.224.193:43579)
I20260812 06:16:24.238758 19369 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:46280
I20260812 06:16:24.239713 19331 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.022580565s
I20260812 06:16:24.251492 19369 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:46282:
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:16:24.265776 19478 tablet_service.cc:1511] Processing CreateTablet for tablet d1a657f6e9e548549e393b09ad7aa47c (DEFAULT_TABLE table=heavy-update-compaction-test [id=f12f3844c3064e10813f34e39d52050b]), partition=
I20260812 06:16:24.266326 19478 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet d1a657f6e9e548549e393b09ad7aa47c. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:24.268682 19536 tablet_bootstrap.cc:492] T d1a657f6e9e548549e393b09ad7aa47c P dabbb03c8b614e029041f01f3b6adcaa: Bootstrap starting.
I20260812 06:16:24.269913 19536 tablet_bootstrap.cc:654] T d1a657f6e9e548549e393b09ad7aa47c P dabbb03c8b614e029041f01f3b6adcaa: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:24.271134 19536 tablet_bootstrap.cc:492] T d1a657f6e9e548549e393b09ad7aa47c P dabbb03c8b614e029041f01f3b6adcaa: No bootstrap required, opened a new log
I20260812 06:16:24.271266 19536 ts_tablet_manager.cc:1403] T d1a657f6e9e548549e393b09ad7aa47c P dabbb03c8b614e029041f01f3b6adcaa: Time spent bootstrapping tablet: real 0.003s	user 0.000s	sys 0.002s
I20260812 06:16:24.271715 19536 raft_consensus.cc:359] T d1a657f6e9e548549e393b09ad7aa47c P dabbb03c8b614e029041f01f3b6adcaa [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "dabbb03c8b614e029041f01f3b6adcaa" member_type: VOTER last_known_addr { host: "127.18.224.193" port: 43579 } }
I20260812 06:16:24.271850 19536 raft_consensus.cc:385] T d1a657f6e9e548549e393b09ad7aa47c P dabbb03c8b614e029041f01f3b6adcaa [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:24.271900 19536 raft_consensus.cc:740] T d1a657f6e9e548549e393b09ad7aa47c P dabbb03c8b614e029041f01f3b6adcaa [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: dabbb03c8b614e029041f01f3b6adcaa, State: Initialized, Role: FOLLOWER
I20260812 06:16:24.272048 19536 consensus_queue.cc:260] T d1a657f6e9e548549e393b09ad7aa47c P dabbb03c8b614e029041f01f3b6adcaa [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: "dabbb03c8b614e029041f01f3b6adcaa" member_type: VOTER last_known_addr { host: "127.18.224.193" port: 43579 } }
I20260812 06:16:24.272164 19536 raft_consensus.cc:399] T d1a657f6e9e548549e393b09ad7aa47c P dabbb03c8b614e029041f01f3b6adcaa [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:24.272217 19536 raft_consensus.cc:493] T d1a657f6e9e548549e393b09ad7aa47c P dabbb03c8b614e029041f01f3b6adcaa [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:24.272274 19536 raft_consensus.cc:3060] T d1a657f6e9e548549e393b09ad7aa47c P dabbb03c8b614e029041f01f3b6adcaa [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:24.273222 19536 raft_consensus.cc:515] T d1a657f6e9e548549e393b09ad7aa47c P dabbb03c8b614e029041f01f3b6adcaa [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "dabbb03c8b614e029041f01f3b6adcaa" member_type: VOTER last_known_addr { host: "127.18.224.193" port: 43579 } }
I20260812 06:16:24.273402 19536 leader_election.cc:304] T d1a657f6e9e548549e393b09ad7aa47c P dabbb03c8b614e029041f01f3b6adcaa [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: dabbb03c8b614e029041f01f3b6adcaa; no voters: 
I20260812 06:16:24.273684 19536 leader_election.cc:290] T d1a657f6e9e548549e393b09ad7aa47c P dabbb03c8b614e029041f01f3b6adcaa [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:24.273989 19539 raft_consensus.cc:2804] T d1a657f6e9e548549e393b09ad7aa47c P dabbb03c8b614e029041f01f3b6adcaa [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:24.274078 19536 ts_tablet_manager.cc:1434] T d1a657f6e9e548549e393b09ad7aa47c P dabbb03c8b614e029041f01f3b6adcaa: Time spent starting tablet: real 0.003s	user 0.000s	sys 0.003s
I20260812 06:16:24.274204 19539 raft_consensus.cc:697] T d1a657f6e9e548549e393b09ad7aa47c P dabbb03c8b614e029041f01f3b6adcaa [term 1 LEADER]: Becoming Leader. State: Replica: dabbb03c8b614e029041f01f3b6adcaa, State: Running, Role: LEADER
I20260812 06:16:24.274348 19539 consensus_queue.cc:237] T d1a657f6e9e548549e393b09ad7aa47c P dabbb03c8b614e029041f01f3b6adcaa [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: "dabbb03c8b614e029041f01f3b6adcaa" member_type: VOTER last_known_addr { host: "127.18.224.193" port: 43579 } }
I20260812 06:16:24.274562 19519 heartbeater.cc:499] Master 127.18.224.254:42071 was elected leader, sending a full tablet report...
I20260812 06:16:24.277360 19369 catalog_manager.cc:5719] T d1a657f6e9e548549e393b09ad7aa47c P dabbb03c8b614e029041f01f3b6adcaa reported cstate change: term changed from 0 to 1, leader changed from <none> to dabbb03c8b614e029041f01f3b6adcaa (127.18.224.193). New cstate: current_term: 1 leader_uuid: "dabbb03c8b614e029041f01f3b6adcaa" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "dabbb03c8b614e029041f01f3b6adcaa" member_type: VOTER last_known_addr { host: "127.18.224.193" port: 43579 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:24.363765 19331 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.077s	user 0.010s	sys 0.023s
I20260812 06:16:24.467664 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling FlushMRSOp(d1a657f6e9e548549e393b09ad7aa47c): perf score=11.117440
I20260812 06:16:24.626133 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: FlushMRSOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.158s	user 0.099s	sys 0.048s Metrics: {"bytes_written":8205078,"cfile_init":1,"compiler_manager_pool.queue_time_us":296,"delete_count":0,"dirs.queue_time_us":64,"dirs.run_cpu_time_us":228,"dirs.run_wall_time_us":922,"drs_written":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4,"lbm_write_time_us":43503,"lbm_writes_lt_1ms":557,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"thread_start_us":186,"threads_started":1,"update_count":1000}
I20260812 06:16:24.627331 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling LogGCOp(d1a657f6e9e548549e393b09ad7aa47c): free 11976772 bytes of WAL
I20260812 06:16:24.627662 19450 log_reader.cc:385] T d1a657f6e9e548549e393b09ad7aa47c: removed 1 log segments from log reader
I20260812 06:16:24.627744 19450 log.cc:1079] T d1a657f6e9e548549e393b09ad7aa47c P dabbb03c8b614e029041f01f3b6adcaa: Deleting log segment in path: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384016249-19331-0/minicluster-data/ts-0-root/wals/d1a657f6e9e548549e393b09ad7aa47c/wal-000000001 (ops 1-6)
I20260812 06:16:24.630209 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: LogGCOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:16:24.630605 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling UndoDeltaBlockGCOp(d1a657f6e9e548549e393b09ad7aa47c): 12308956 bytes on disk
I20260812 06:16:24.631166 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: UndoDeltaBlockGCOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4}
I20260812 06:16:24.631549 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c): perf score=2.188937
I20260812 06:16:24.646733 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.015s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5755,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:24.647190 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling MajorDeltaCompactionOp(d1a657f6e9e548549e393b09ad7aa47c): perf score=1.000000
I20260812 06:16:24.758046 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: MajorDeltaCompactionOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.111s	user 0.084s	sys 0.025s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16528900,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1231,"lbm_read_time_us":6142,"lbm_reads_lt_1ms":360,"lbm_write_time_us":23864,"lbm_writes_lt_1ms":343,"mutex_wait_us":163,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":373,"threads_started":5,"update_count":1500}
I20260812 06:16:24.758636 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c): perf score=7.149875
I20260812 06:16:24.786875 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.028s	user 0.019s	sys 0.008s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":13693,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:16:24.787446 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c): perf score=2.188937
I20260812 06:16:24.804725 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.017s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5419,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:24.805248 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling MajorDeltaCompactionOp(d1a657f6e9e548549e393b09ad7aa47c): perf score=1.000000
I20260812 06:16:24.935303 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: MajorDeltaCompactionOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.130s	user 0.100s	sys 0.030s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16528891,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":169,"lbm_read_time_us":6876,"lbm_reads_lt_1ms":364,"lbm_write_time_us":38694,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":342,"mutex_wait_us":28,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":35840,"update_count":1500}
I20260812 06:16:24.935967 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c): perf score=10.126437
I20260812 06:16:24.982638 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.046s	user 0.011s	sys 0.026s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16365,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:24.983091 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c): perf score=2.188937
I20260812 06:16:24.994457 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.011s	user 0.009s	sys 0.000s 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:16:24.995098 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling MajorDeltaCompactionOp(d1a657f6e9e548549e393b09ad7aa47c): perf score=1.000000
I20260812 06:16:25.132529 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: MajorDeltaCompactionOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.137s	user 0.107s	sys 0.025s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":336,"lbm_read_time_us":7767,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29909,"lbm_writes_lt_1ms":443,"mutex_wait_us":54,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9088,"update_count":2000}
I20260812 06:16:25.133184 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c): perf score=10.126437
I20260812 06:16:25.170061 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.037s	user 0.016s	sys 0.016s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15321,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:25.170652 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling MajorDeltaCompactionOp(d1a657f6e9e548549e393b09ad7aa47c): perf score=1.000000
I20260812 06:16:25.279655 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: MajorDeltaCompactionOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.109s	user 0.088s	sys 0.020s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16528782,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":590,"lbm_read_time_us":5935,"lbm_reads_lt_1ms":363,"lbm_write_time_us":20082,"lbm_writes_lt_1ms":343,"mutex_wait_us":285,"peak_mem_usage":38262756,"reinsert_count":0,"update_count":1500}
I20260812 06:16:25.280459 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c): perf score=10.126437
I20260812 06:16:25.318540 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.038s	user 0.023s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16992,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:25.319001 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling MajorDeltaCompactionOp(d1a657f6e9e548549e393b09ad7aa47c): perf score=1.000000
I20260812 06:16:25.444789 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: MajorDeltaCompactionOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.126s	user 0.080s	sys 0.043s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16528781,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":964,"lbm_read_time_us":7205,"lbm_reads_lt_1ms":367,"lbm_write_time_us":22208,"lbm_writes_lt_1ms":343,"mutex_wait_us":341,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":18688,"update_count":1500}
I20260812 06:16:25.445363 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c): perf score=10.126437
I20260812 06:16:25.488106 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.043s	user 0.023s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18919,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:25.488668 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling MajorDeltaCompactionOp(d1a657f6e9e548549e393b09ad7aa47c): perf score=1.000000
I20260812 06:16:25.619446 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: MajorDeltaCompactionOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.131s	user 0.122s	sys 0.007s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16528781,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":732,"lbm_read_time_us":6771,"lbm_reads_lt_1ms":363,"lbm_write_time_us":24963,"lbm_writes_lt_1ms":343,"mutex_wait_us":23,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":7040,"update_count":1500}
I20260812 06:16:25.620167 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c): perf score=10.126437
I20260812 06:16:25.663291 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.043s	user 0.014s	sys 0.019s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":15105,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:25.663818 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c): perf score=2.188937
I20260812 06:16:25.680205 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.016s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6015,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:25.681030 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling MajorDeltaCompactionOp(d1a657f6e9e548549e393b09ad7aa47c): perf score=1.000000
I20260812 06:16:25.813753 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: MajorDeltaCompactionOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.133s	user 0.112s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631314,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":850,"lbm_read_time_us":8652,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28212,"lbm_writes_lt_1ms":443,"mutex_wait_us":95,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":2000}
I20260812 06:16:25.814445 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c): perf score=10.126437
I20260812 06:16:25.869078 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.054s	user 0.037s	sys 0.007s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17774,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:25.869715 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c): perf score=2.188937
I20260812 06:16:25.881098 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4319,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:25.881629 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling MajorDeltaCompactionOp(d1a657f6e9e548549e393b09ad7aa47c): perf score=1.000000
I20260812 06:16:26.043733 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: MajorDeltaCompactionOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.162s	user 0.107s	sys 0.046s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":161,"lbm_read_time_us":10452,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26923,"lbm_writes_lt_1ms":443,"mutex_wait_us":71,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14208,"update_count":2000}
I20260812 06:16:26.044556 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c): perf score=10.126437
I20260812 06:16:26.094638 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.050s	user 0.020s	sys 0.017s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16299,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:26.095170 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c): perf score=2.188937
I20260812 06:16:26.107268 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4438,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:26.107796 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling FlushMRSOp(d1a657f6e9e548549e393b09ad7aa47c): perf score=1.000000
I20260812 06:16:26.139277 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: FlushMRSOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.031s	user 0.026s	sys 0.005s Metrics: {"bytes_written":1275444,"cfile_init":1,"dirs.queue_time_us":92,"dirs.run_cpu_time_us":259,"dirs.run_wall_time_us":1341,"drs_written":1,"lbm_read_time_us":46,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1773,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:16:26.140087 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling LogGCOp(d1a657f6e9e548549e393b09ad7aa47c): free 133477359 bytes of WAL
I20260812 06:16:26.140327 19450 log_reader.cc:385] T d1a657f6e9e548549e393b09ad7aa47c: removed 13 log segments from log reader
I20260812 06:16:26.140393 19450 log.cc:1079] T d1a657f6e9e548549e393b09ad7aa47c P dabbb03c8b614e029041f01f3b6adcaa: Deleting log segment in path: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384016249-19331-0/minicluster-data/ts-0-root/wals/d1a657f6e9e548549e393b09ad7aa47c/wal-000000002 (ops 7-11)
I20260812 06:16:26.140444 19450 log.cc:1079] T d1a657f6e9e548549e393b09ad7aa47c P dabbb03c8b614e029041f01f3b6adcaa: Deleting log segment in path: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384016249-19331-0/minicluster-data/ts-0-root/wals/d1a657f6e9e548549e393b09ad7aa47c/wal-000000003 (ops 12-16)
I20260812 06:16:26.140502 19450 log.cc:1079] T d1a657f6e9e548549e393b09ad7aa47c P dabbb03c8b614e029041f01f3b6adcaa: Deleting log segment in path: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384016249-19331-0/minicluster-data/ts-0-root/wals/d1a657f6e9e548549e393b09ad7aa47c/wal-000000004 (ops 17-21)
I20260812 06:16:26.140545 19450 log.cc:1079] T d1a657f6e9e548549e393b09ad7aa47c P dabbb03c8b614e029041f01f3b6adcaa: Deleting log segment in path: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384016249-19331-0/minicluster-data/ts-0-root/wals/d1a657f6e9e548549e393b09ad7aa47c/wal-000000005 (ops 22-26)
I20260812 06:16:26.140594 19450 log.cc:1079] T d1a657f6e9e548549e393b09ad7aa47c P dabbb03c8b614e029041f01f3b6adcaa: Deleting log segment in path: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384016249-19331-0/minicluster-data/ts-0-root/wals/d1a657f6e9e548549e393b09ad7aa47c/wal-000000006 (ops 27-31)
I20260812 06:16:26.140633 19450 log.cc:1079] T d1a657f6e9e548549e393b09ad7aa47c P dabbb03c8b614e029041f01f3b6adcaa: Deleting log segment in path: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384016249-19331-0/minicluster-data/ts-0-root/wals/d1a657f6e9e548549e393b09ad7aa47c/wal-000000007 (ops 32-36)
I20260812 06:16:26.140671 19450 log.cc:1079] T d1a657f6e9e548549e393b09ad7aa47c P dabbb03c8b614e029041f01f3b6adcaa: Deleting log segment in path: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384016249-19331-0/minicluster-data/ts-0-root/wals/d1a657f6e9e548549e393b09ad7aa47c/wal-000000008 (ops 37-41)
I20260812 06:16:26.140709 19450 log.cc:1079] T d1a657f6e9e548549e393b09ad7aa47c P dabbb03c8b614e029041f01f3b6adcaa: Deleting log segment in path: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384016249-19331-0/minicluster-data/ts-0-root/wals/d1a657f6e9e548549e393b09ad7aa47c/wal-000000009 (ops 42-46)
I20260812 06:16:26.140748 19450 log.cc:1079] T d1a657f6e9e548549e393b09ad7aa47c P dabbb03c8b614e029041f01f3b6adcaa: Deleting log segment in path: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384016249-19331-0/minicluster-data/ts-0-root/wals/d1a657f6e9e548549e393b09ad7aa47c/wal-000000010 (ops 47-51)
I20260812 06:16:26.140785 19450 log.cc:1079] T d1a657f6e9e548549e393b09ad7aa47c P dabbb03c8b614e029041f01f3b6adcaa: Deleting log segment in path: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384016249-19331-0/minicluster-data/ts-0-root/wals/d1a657f6e9e548549e393b09ad7aa47c/wal-000000011 (ops 52-56)
I20260812 06:16:26.140825 19450 log.cc:1079] T d1a657f6e9e548549e393b09ad7aa47c P dabbb03c8b614e029041f01f3b6adcaa: Deleting log segment in path: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384016249-19331-0/minicluster-data/ts-0-root/wals/d1a657f6e9e548549e393b09ad7aa47c/wal-000000012 (ops 57-61)
I20260812 06:16:26.140862 19450 log.cc:1079] T d1a657f6e9e548549e393b09ad7aa47c P dabbb03c8b614e029041f01f3b6adcaa: Deleting log segment in path: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384016249-19331-0/minicluster-data/ts-0-root/wals/d1a657f6e9e548549e393b09ad7aa47c/wal-000000013 (ops 62-66)
I20260812 06:16:26.140900 19450 log.cc:1079] T d1a657f6e9e548549e393b09ad7aa47c P dabbb03c8b614e029041f01f3b6adcaa: Deleting log segment in path: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384016249-19331-0/minicluster-data/ts-0-root/wals/d1a657f6e9e548549e393b09ad7aa47c/wal-000000014 (ops 67-71)
I20260812 06:16:26.172585 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: LogGCOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.032s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:16:26.173017 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c): perf score=3.181125
I20260812 06:16:26.191494 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.018s	user 0.004s	sys 0.013s Metrics: {"bytes_written":4553933,"delete_count":0,"lbm_write_time_us":7632,"lbm_writes_lt_1ms":114,"reinsert_count":0,"update_count":555}
I20260812 06:16:26.191987 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c): perf score=2.188937
I20260812 06:16:26.210210 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.018s	user 0.007s	sys 0.007s Metrics: {"bytes_written":3651380,"delete_count":0,"lbm_write_time_us":3847,"lbm_writes_lt_1ms":92,"reinsert_count":0,"update_count":445}
I20260812 06:16:26.210769 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling MajorDeltaCompactionOp(d1a657f6e9e548549e393b09ad7aa47c): perf score=1.000000
I20260812 06:16:26.431485 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: MajorDeltaCompactionOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.221s	user 0.160s	sys 0.052s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836368,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":673,"lbm_read_time_us":16508,"lbm_reads_lt_1ms":674,"lbm_write_time_us":38215,"lbm_writes_lt_1ms":643,"mutex_wait_us":313,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":12032,"thread_start_us":100,"threads_started":1,"update_count":3000}
I20260812 06:16:26.432322 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c): perf score=14.095187
I20260812 06:16:26.496066 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.064s	user 0.035s	sys 0.027s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":26210,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:16:26.496794 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling UndoDeltaBlockGCOp(d1a657f6e9e548549e393b09ad7aa47c): 482 bytes on disk
I20260812 06:16:26.497395 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: UndoDeltaBlockGCOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":82,"lbm_reads_lt_1ms":4}
I20260812 06:16:26.498032 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c): perf score=2.188937
I20260812 06:16:26.508839 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4068,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:26.509332 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling MajorDeltaCompactionOp(d1a657f6e9e548549e393b09ad7aa47c): perf score=1.000000
I20260812 06:16:26.677101 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: MajorDeltaCompactionOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.168s	user 0.115s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":345,"lbm_read_time_us":12526,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29008,"lbm_writes_lt_1ms":543,"mutex_wait_us":73,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2500}
I20260812 06:16:26.677632 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c): perf score=10.126437
I20260812 06:16:26.713085 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.034s	user 0.011s	sys 0.021s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":14811,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:26.713696 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c): perf score=2.188937
I20260812 06:16:26.730316 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.016s	user 0.007s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6300,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:26.732053 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling MajorDeltaCompactionOp(d1a657f6e9e548549e393b09ad7aa47c): perf score=1.000000
I20260812 06:16:26.858875 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: MajorDeltaCompactionOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.127s	user 0.110s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631314,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":690,"lbm_read_time_us":9980,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22731,"lbm_writes_lt_1ms":443,"mutex_wait_us":338,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":21504,"update_count":2000}
I20260812 06:16:26.859525 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c): perf score=10.126437
I20260812 06:16:26.906205 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.046s	user 0.025s	sys 0.008s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15597,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:26.906801 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c): perf score=2.188937
I20260812 06:16:26.918911 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4452,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:26.919545 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling MajorDeltaCompactionOp(d1a657f6e9e548549e393b09ad7aa47c): perf score=1.000000
I20260812 06:16:27.045660 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: MajorDeltaCompactionOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.126s	user 0.101s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631310,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1607,"lbm_read_time_us":8499,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23415,"lbm_writes_lt_1ms":443,"mutex_wait_us":544,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":20608,"update_count":2000}
I20260812 06:16:27.046396 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c): perf score=10.126437
I20260812 06:16:27.085635 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.039s	user 0.020s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16088,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:27.086264 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c): perf score=2.188937
I20260812 06:16:27.098774 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.012s	user 0.005s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4471,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:27.099473 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling MajorDeltaCompactionOp(d1a657f6e9e548549e393b09ad7aa47c): perf score=1.000000
I20260812 06:16:27.223680 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: MajorDeltaCompactionOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.124s	user 0.075s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1138,"lbm_read_time_us":7639,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25400,"lbm_writes_lt_1ms":443,"mutex_wait_us":351,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:16:27.224450 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c): perf score=11.118625
I20260812 06:16:27.275315 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.051s	user 0.021s	sys 0.029s Metrics: {"bytes_written":12512611,"delete_count":0,"lbm_write_time_us":22451,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":305,"reinsert_count":0,"update_count":1525}
I20260812 06:16:27.275967 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c): perf score=2.188937
I20260812 06:16:27.288163 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.012s	user 0.004s	sys 0.006s Metrics: {"bytes_written":3897534,"delete_count":0,"lbm_write_time_us":4404,"lbm_writes_lt_1ms":98,"reinsert_count":0,"update_count":475}
I20260812 06:16:27.288762 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling MajorDeltaCompactionOp(d1a657f6e9e548549e393b09ad7aa47c): perf score=1.000000
I20260812 06:16:27.436280 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: MajorDeltaCompactionOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.147s	user 0.108s	sys 0.039s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631308,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":163,"lbm_read_time_us":10459,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24907,"lbm_writes_lt_1ms":443,"mutex_wait_us":41,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:16:27.437052 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c): perf score=10.126437
I20260812 06:16:27.474012 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.037s	user 0.014s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14185,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:27.474767 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c): perf score=2.188937
I20260812 06:16:27.488269 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.013s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5066,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:27.488839 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling MajorDeltaCompactionOp(d1a657f6e9e548549e393b09ad7aa47c): perf score=1.000000
I20260812 06:16:27.616390 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: MajorDeltaCompactionOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.127s	user 0.100s	sys 0.027s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":550,"lbm_read_time_us":9847,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24573,"lbm_writes_lt_1ms":443,"mutex_wait_us":45,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9600,"update_count":2000}
I20260812 06:16:27.617545 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c): perf score=10.126437
I20260812 06:16:27.656840 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.039s	user 0.020s	sys 0.017s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16417,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:27.657572 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c): perf score=2.188937
I20260812 06:16:27.674270 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.016s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6272,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:27.676236 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling FlushMRSOp(d1a657f6e9e548549e393b09ad7aa47c): perf score=1.000000
I20260812 06:16:27.703519 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: FlushMRSOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.027s	user 0.026s	sys 0.000s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":77,"dirs.run_cpu_time_us":243,"dirs.run_wall_time_us":1541,"drs_written":1,"lbm_read_time_us":46,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1761,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:16:27.704408 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling LogGCOp(d1a657f6e9e548549e393b09ad7aa47c): free 121006508 bytes of WAL
I20260812 06:16:27.704708 19450 log_reader.cc:385] T d1a657f6e9e548549e393b09ad7aa47c: removed 12 log segments from log reader
I20260812 06:16:27.704787 19450 log.cc:1079] T d1a657f6e9e548549e393b09ad7aa47c P dabbb03c8b614e029041f01f3b6adcaa: Deleting log segment in path: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384016249-19331-0/minicluster-data/ts-0-root/wals/d1a657f6e9e548549e393b09ad7aa47c/wal-000000015 (ops 72-76)
I20260812 06:16:27.704841 19450 log.cc:1079] T d1a657f6e9e548549e393b09ad7aa47c P dabbb03c8b614e029041f01f3b6adcaa: Deleting log segment in path: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384016249-19331-0/minicluster-data/ts-0-root/wals/d1a657f6e9e548549e393b09ad7aa47c/wal-000000016 (ops 77-81)
I20260812 06:16:27.704877 19450 log.cc:1079] T d1a657f6e9e548549e393b09ad7aa47c P dabbb03c8b614e029041f01f3b6adcaa: Deleting log segment in path: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384016249-19331-0/minicluster-data/ts-0-root/wals/d1a657f6e9e548549e393b09ad7aa47c/wal-000000017 (ops 82-86)
I20260812 06:16:27.704916 19450 log.cc:1079] T d1a657f6e9e548549e393b09ad7aa47c P dabbb03c8b614e029041f01f3b6adcaa: Deleting log segment in path: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384016249-19331-0/minicluster-data/ts-0-root/wals/d1a657f6e9e548549e393b09ad7aa47c/wal-000000018 (ops 87-91)
I20260812 06:16:27.704952 19450 log.cc:1079] T d1a657f6e9e548549e393b09ad7aa47c P dabbb03c8b614e029041f01f3b6adcaa: Deleting log segment in path: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384016249-19331-0/minicluster-data/ts-0-root/wals/d1a657f6e9e548549e393b09ad7aa47c/wal-000000019 (ops 92-96)
I20260812 06:16:27.704988 19450 log.cc:1079] T d1a657f6e9e548549e393b09ad7aa47c P dabbb03c8b614e029041f01f3b6adcaa: Deleting log segment in path: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384016249-19331-0/minicluster-data/ts-0-root/wals/d1a657f6e9e548549e393b09ad7aa47c/wal-000000020 (ops 97-101)
I20260812 06:16:27.705022 19450 log.cc:1079] T d1a657f6e9e548549e393b09ad7aa47c P dabbb03c8b614e029041f01f3b6adcaa: Deleting log segment in path: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384016249-19331-0/minicluster-data/ts-0-root/wals/d1a657f6e9e548549e393b09ad7aa47c/wal-000000021 (ops 102-106)
I20260812 06:16:27.705053 19450 log.cc:1079] T d1a657f6e9e548549e393b09ad7aa47c P dabbb03c8b614e029041f01f3b6adcaa: Deleting log segment in path: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384016249-19331-0/minicluster-data/ts-0-root/wals/d1a657f6e9e548549e393b09ad7aa47c/wal-000000022 (ops 107-110)
I20260812 06:16:27.705091 19450 log.cc:1079] T d1a657f6e9e548549e393b09ad7aa47c P dabbb03c8b614e029041f01f3b6adcaa: Deleting log segment in path: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384016249-19331-0/minicluster-data/ts-0-root/wals/d1a657f6e9e548549e393b09ad7aa47c/wal-000000023 (ops 111-115)
I20260812 06:16:27.705127 19450 log.cc:1079] T d1a657f6e9e548549e393b09ad7aa47c P dabbb03c8b614e029041f01f3b6adcaa: Deleting log segment in path: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384016249-19331-0/minicluster-data/ts-0-root/wals/d1a657f6e9e548549e393b09ad7aa47c/wal-000000024 (ops 116-120)
I20260812 06:16:27.705165 19450 log.cc:1079] T d1a657f6e9e548549e393b09ad7aa47c P dabbb03c8b614e029041f01f3b6adcaa: Deleting log segment in path: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384016249-19331-0/minicluster-data/ts-0-root/wals/d1a657f6e9e548549e393b09ad7aa47c/wal-000000025 (ops 121-125)
I20260812 06:16:27.705202 19450 log.cc:1079] T d1a657f6e9e548549e393b09ad7aa47c P dabbb03c8b614e029041f01f3b6adcaa: Deleting log segment in path: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384016249-19331-0/minicluster-data/ts-0-root/wals/d1a657f6e9e548549e393b09ad7aa47c/wal-000000026 (ops 126-130)
I20260812 06:16:27.730222 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: LogGCOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.026s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:16:27.730763 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c): perf score=3.181125
I20260812 06:16:27.746054 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.015s	user 0.005s	sys 0.008s Metrics: {"bytes_written":5087239,"delete_count":0,"lbm_write_time_us":6037,"lbm_writes_lt_1ms":127,"reinsert_count":0,"update_count":620}
I20260812 06:16:27.746670 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling UndoDeltaBlockGCOp(d1a657f6e9e548549e393b09ad7aa47c): 483 bytes on disk
I20260812 06:16:27.747177 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: UndoDeltaBlockGCOp(d1a657f6e9e548549e393b09ad7aa47c) 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:16:27.747821 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c): perf score=1.196750
I20260812 06:16:27.761469 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3118055,"delete_count":0,"lbm_write_time_us":5176,"lbm_writes_lt_1ms":79,"reinsert_count":0,"update_count":380}
I20260812 06:16:27.761999 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling MajorDeltaCompactionOp(d1a657f6e9e548549e393b09ad7aa47c): perf score=1.000000
I20260812 06:16:27.938692 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: MajorDeltaCompactionOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.177s	user 0.129s	sys 0.043s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836349,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":617,"lbm_read_time_us":11158,"lbm_reads_lt_1ms":674,"lbm_write_time_us":36389,"lbm_writes_lt_1ms":643,"mutex_wait_us":319,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":4608,"thread_start_us":81,"threads_started":1,"update_count":3000}
I20260812 06:16:27.939513 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c): perf score=14.095187
I20260812 06:16:27.991230 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.051s	user 0.029s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18783,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:27.991891 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c): perf score=2.188937
I20260812 06:16:28.004499 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.012s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4463,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:28.005049 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling MajorDeltaCompactionOp(d1a657f6e9e548549e393b09ad7aa47c): perf score=1.000000
I20260812 06:16:28.180006 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: MajorDeltaCompactionOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.175s	user 0.132s	sys 0.032s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733722,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":336,"lbm_read_time_us":13274,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32366,"lbm_writes_lt_1ms":543,"mutex_wait_us":31,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":98560,"update_count":2500}
I20260812 06:16:28.180733 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c): perf score=14.095187
I20260812 06:16:28.234570 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.054s	user 0.015s	sys 0.032s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23374,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:16:28.235206 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling MajorDeltaCompactionOp(d1a657f6e9e548549e393b09ad7aa47c): perf score=1.000000
I20260812 06:16:28.392997 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: MajorDeltaCompactionOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.158s	user 0.100s	sys 0.057s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20631192,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":628,"lbm_read_time_us":11623,"lbm_reads_lt_1ms":463,"lbm_write_time_us":27991,"lbm_writes_lt_1ms":443,"mutex_wait_us":254,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:16:28.393666 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c): perf score=11.118625
I20260812 06:16:28.430123 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.036s	user 0.026s	sys 0.007s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16363,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:28.430876 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c): perf score=2.188937
I20260812 06:16:28.447463 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.016s	user 0.007s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6216,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:28.448132 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling MajorDeltaCompactionOp(d1a657f6e9e548549e393b09ad7aa47c): perf score=1.000000
I20260812 06:16:28.599411 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: MajorDeltaCompactionOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.151s	user 0.117s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631303,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1818,"lbm_read_time_us":12240,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28841,"lbm_writes_lt_1ms":443,"mutex_wait_us":392,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8576,"update_count":2000}
I20260812 06:16:28.600845 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c): perf score=10.126437
I20260812 06:16:28.643672 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.043s	user 0.029s	sys 0.012s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":20557,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:16:28.644263 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c): perf score=2.188937
I20260812 06:16:28.662021 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.018s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5946,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:28.662686 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling MajorDeltaCompactionOp(d1a657f6e9e548549e393b09ad7aa47c): perf score=1.000000
I20260812 06:16:28.792471 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: MajorDeltaCompactionOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.130s	user 0.113s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":189,"lbm_read_time_us":7575,"lbm_reads_lt_1ms":464,"lbm_write_time_us":28454,"lbm_writes_lt_1ms":443,"mutex_wait_us":40,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13056,"update_count":2000}
I20260812 06:16:28.793210 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c): perf score=10.126437
I20260812 06:16:28.837246 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.044s	user 0.017s	sys 0.024s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20576,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:28.837881 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c): perf score=2.188937
I20260812 06:16:28.852016 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4847,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:28.852854 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling MajorDeltaCompactionOp(d1a657f6e9e548549e393b09ad7aa47c): perf score=1.000000
I20260812 06:16:28.992015 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: MajorDeltaCompactionOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.139s	user 0.099s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1293,"lbm_read_time_us":10134,"lbm_reads_lt_1ms":472,"lbm_write_time_us":31509,"lbm_writes_lt_1ms":443,"mutex_wait_us":287,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:16:28.992563 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c): perf score=11.118625
I20260812 06:16:29.044636 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.052s	user 0.017s	sys 0.031s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":21231,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:16:29.045369 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c): perf score=3.181125
I20260812 06:16:29.065094 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.020s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4964166,"delete_count":0,"lbm_write_time_us":9285,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":123,"reinsert_count":0,"update_count":605}
I20260812 06:16:29.065711 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c): perf score=1.196750
I20260812 06:16:29.079690 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.014s	user 0.007s	sys 0.005s Metrics: {"bytes_written":2830880,"delete_count":0,"lbm_write_time_us":5005,"lbm_writes_lt_1ms":72,"reinsert_count":0,"update_count":345}
I20260812 06:16:29.080476 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling FlushMRSOp(d1a657f6e9e548549e393b09ad7aa47c): perf score=1.000000
I20260812 06:16:29.108731 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: FlushMRSOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.028s	user 0.024s	sys 0.000s Metrics: {"bytes_written":1152512,"cfile_init":1,"dirs.queue_time_us":66,"dirs.run_cpu_time_us":236,"dirs.run_wall_time_us":1327,"drs_written":1,"lbm_read_time_us":88,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1410,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:16:29.109460 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling LogGCOp(d1a657f6e9e548549e393b09ad7aa47c): free 115943375 bytes of WAL
I20260812 06:16:29.109714 19450 log_reader.cc:385] T d1a657f6e9e548549e393b09ad7aa47c: removed 11 log segments from log reader
I20260812 06:16:29.109758 19450 log.cc:1079] T d1a657f6e9e548549e393b09ad7aa47c P dabbb03c8b614e029041f01f3b6adcaa: Deleting log segment in path: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384016249-19331-0/minicluster-data/ts-0-root/wals/d1a657f6e9e548549e393b09ad7aa47c/wal-000000027 (ops 131-135)
I20260812 06:16:29.109788 19450 log.cc:1079] T d1a657f6e9e548549e393b09ad7aa47c P dabbb03c8b614e029041f01f3b6adcaa: Deleting log segment in path: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384016249-19331-0/minicluster-data/ts-0-root/wals/d1a657f6e9e548549e393b09ad7aa47c/wal-000000028 (ops 136-140)
I20260812 06:16:29.109855 19450 log.cc:1079] T d1a657f6e9e548549e393b09ad7aa47c P dabbb03c8b614e029041f01f3b6adcaa: Deleting log segment in path: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384016249-19331-0/minicluster-data/ts-0-root/wals/d1a657f6e9e548549e393b09ad7aa47c/wal-000000029 (ops 141-145)
I20260812 06:16:29.109902 19450 log.cc:1079] T d1a657f6e9e548549e393b09ad7aa47c P dabbb03c8b614e029041f01f3b6adcaa: Deleting log segment in path: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384016249-19331-0/minicluster-data/ts-0-root/wals/d1a657f6e9e548549e393b09ad7aa47c/wal-000000030 (ops 146-150)
I20260812 06:16:29.109939 19450 log.cc:1079] T d1a657f6e9e548549e393b09ad7aa47c P dabbb03c8b614e029041f01f3b6adcaa: Deleting log segment in path: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384016249-19331-0/minicluster-data/ts-0-root/wals/d1a657f6e9e548549e393b09ad7aa47c/wal-000000031 (ops 151-155)
I20260812 06:16:29.110014 19450 log.cc:1079] T d1a657f6e9e548549e393b09ad7aa47c P dabbb03c8b614e029041f01f3b6adcaa: Deleting log segment in path: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384016249-19331-0/minicluster-data/ts-0-root/wals/d1a657f6e9e548549e393b09ad7aa47c/wal-000000032 (ops 156-160)
I20260812 06:16:29.110049 19450 log.cc:1079] T d1a657f6e9e548549e393b09ad7aa47c P dabbb03c8b614e029041f01f3b6adcaa: Deleting log segment in path: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384016249-19331-0/minicluster-data/ts-0-root/wals/d1a657f6e9e548549e393b09ad7aa47c/wal-000000033 (ops 161-165)
I20260812 06:16:29.110086 19450 log.cc:1079] T d1a657f6e9e548549e393b09ad7aa47c P dabbb03c8b614e029041f01f3b6adcaa: Deleting log segment in path: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384016249-19331-0/minicluster-data/ts-0-root/wals/d1a657f6e9e548549e393b09ad7aa47c/wal-000000034 (ops 166-170)
I20260812 06:16:29.110124 19450 log.cc:1079] T d1a657f6e9e548549e393b09ad7aa47c P dabbb03c8b614e029041f01f3b6adcaa: Deleting log segment in path: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384016249-19331-0/minicluster-data/ts-0-root/wals/d1a657f6e9e548549e393b09ad7aa47c/wal-000000035 (ops 171-175)
I20260812 06:16:29.110162 19450 log.cc:1079] T d1a657f6e9e548549e393b09ad7aa47c P dabbb03c8b614e029041f01f3b6adcaa: Deleting log segment in path: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384016249-19331-0/minicluster-data/ts-0-root/wals/d1a657f6e9e548549e393b09ad7aa47c/wal-000000036 (ops 176-180)
I20260812 06:16:29.110203 19450 log.cc:1079] T d1a657f6e9e548549e393b09ad7aa47c P dabbb03c8b614e029041f01f3b6adcaa: Deleting log segment in path: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384016249-19331-0/minicluster-data/ts-0-root/wals/d1a657f6e9e548549e393b09ad7aa47c/wal-000000037 (ops 181-185)
I20260812 06:16:29.136035 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: LogGCOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.026s	user 0.002s	sys 0.023s Metrics: {}
I20260812 06:16:29.136566 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c): perf score=2.188937
I20260812 06:16:29.158301 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.021s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6500,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:29.158816 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling LogGCOp(d1a657f6e9e548549e393b09ad7aa47c): free 12018012 bytes of WAL
I20260812 06:16:29.159045 19450 log_reader.cc:385] T d1a657f6e9e548549e393b09ad7aa47c: removed 1 log segments from log reader
I20260812 06:16:29.159092 19450 log.cc:1079] T d1a657f6e9e548549e393b09ad7aa47c P dabbb03c8b614e029041f01f3b6adcaa: Deleting log segment in path: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384016249-19331-0/minicluster-data/ts-0-root/wals/d1a657f6e9e548549e393b09ad7aa47c/wal-000000038 (ops 186-190)
I20260812 06:16:29.161475 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: LogGCOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:16:29.161844 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling UndoDeltaBlockGCOp(d1a657f6e9e548549e393b09ad7aa47c): 447 bytes on disk
I20260812 06:16:29.162304 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: UndoDeltaBlockGCOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4}
I20260812 06:16:29.162878 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c): perf score=2.188937
I20260812 06:16:29.175199 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.012s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4629,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:29.175757 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling MajorDeltaCompactionOp(d1a657f6e9e548549e393b09ad7aa47c): perf score=1.000000
I20260812 06:16:29.388603 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: MajorDeltaCompactionOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.213s	user 0.136s	sys 0.076s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32938877,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":209,"lbm_read_time_us":15696,"lbm_reads_lt_1ms":775,"lbm_write_time_us":40377,"lbm_writes_lt_1ms":743,"mutex_wait_us":36,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":144640,"thread_start_us":83,"threads_started":1,"update_count":3500}
I20260812 06:16:29.389374 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c): perf score=14.095187
I20260812 06:16:29.418165 19331 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.054s	user 1.851s	sys 0.138s
I20260812 06:16:29.431080 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.042s	user 0.029s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19403,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:29.431632 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c): perf score=2.188937
I20260812 06:16:29.444785 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: FlushDeltaMemStoresOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4837,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:29.445271 19522 maintenance_manager.cc:419] P dabbb03c8b614e029041f01f3b6adcaa: Scheduling MajorDeltaCompactionOp(d1a657f6e9e548549e393b09ad7aa47c): perf score=1.000000
I20260812 06:16:29.455991 19331 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.037s	user 0.004s	sys 0.000s
I20260812 06:16:29.456835 19331 tablet_server.cc:179] TabletServer@127.18.224.193:0 shutting down...
I20260812 06:16:29.566421 19450 maintenance_manager.cc:643] P dabbb03c8b614e029041f01f3b6adcaa: MajorDeltaCompactionOp(d1a657f6e9e548549e393b09ad7aa47c) complete. Timing: real 0.121s	user 0.097s	sys 0.024s Metrics: {"cfile_cache_hit":30,"cfile_cache_hit_bytes":4221425,"cfile_cache_miss":502,"cfile_cache_miss_bytes":20512297,"cfile_init":4,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":421,"lbm_read_time_us":8582,"lbm_reads_lt_1ms":518,"lbm_write_time_us":24998,"lbm_writes_lt_1ms":543,"mutex_wait_us":21,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":21888,"update_count":2500}
I20260812 06:16:29.567204 19331 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:16:29.567708 19331 tablet_replica.cc:333] T d1a657f6e9e548549e393b09ad7aa47c P dabbb03c8b614e029041f01f3b6adcaa: stopping tablet replica
I20260812 06:16:29.567952 19331 raft_consensus.cc:2243] T d1a657f6e9e548549e393b09ad7aa47c P dabbb03c8b614e029041f01f3b6adcaa [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:29.568200 19331 raft_consensus.cc:2272] T d1a657f6e9e548549e393b09ad7aa47c P dabbb03c8b614e029041f01f3b6adcaa [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:29.584177 19331 tablet_server.cc:196] TabletServer@127.18.224.193:0 shutdown complete.
I20260812 06:16:29.613754 19331 master.cc:562] Master@127.18.224.254:42071 shutting down...
I20260812 06:16:29.618564 19331 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 1399a77633fe4b3c846801175eb2f21a [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:29.618777 19331 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 1399a77633fe4b3c846801175eb2f21a [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:29.618876 19331 tablet_replica.cc:333] T 00000000000000000000000000000000 P 1399a77633fe4b3c846801175eb2f21a: stopping tablet replica
I20260812 06:16:29.631430 19331 master.cc:584] Master@127.18.224.254:42071 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5695 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:16:29.735229 19331 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.18.224.254:42193
I20260812 06:16:29.735690 19331 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:29.738710 19559 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:16:29.738854 19331 server_base.cc:1061] running on GCE node
W20260812 06:16:29.738714 19563 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:16:29.738958 19561 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:16:29.739298 19331 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:29.739351 19331 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:16:29.739367 19331 hybrid_clock.cc:648] HybridClock initialized: now 1786515389739368 us; error 0 us; skew 500 ppm
I20260812 06:16:29.740330 19331 webserver.cc:533] Webserver started at http://127.18.224.254:42657/ using document root <none> and password file <none>
I20260812 06:16:29.740501 19331 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:29.740577 19331 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:29.740638 19331 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:29.741035 19331 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384016249-19331-0/minicluster-data/master-0-root/instance:
uuid: "8b48d55544984814a74a817e7003247e"
format_stamp: "Formatted at 2026-08-12 06:16:29 on dist-test-slave-5l3k"
I20260812 06:16:29.742787 19331 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:16:29.743979 19568 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:16:29.744234 19331 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:29.744307 19331 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384016249-19331-0/minicluster-data/master-0-root
uuid: "8b48d55544984814a74a817e7003247e"
format_stamp: "Formatted at 2026-08-12 06:16:29 on dist-test-slave-5l3k"
I20260812 06:16:29.744372 19331 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384016249-19331-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384016249-19331-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384016249-19331-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:16:29.767303 19331 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:29.767733 19331 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:29.772931 19331 rpc_server.cc:307] RPC server started. Bound to: 127.18.224.254:42193
I20260812 06:16:29.776883 19626 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.18.224.254:42193 every 8 connection(s)
I20260812 06:16:29.777470 19627 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:16:29.779563 19627 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 8b48d55544984814a74a817e7003247e: Bootstrap starting.
I20260812 06:16:29.780457 19627 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 8b48d55544984814a74a817e7003247e: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:29.781850 19627 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 8b48d55544984814a74a817e7003247e: No bootstrap required, opened a new log
I20260812 06:16:29.782826 19627 raft_consensus.cc:359] T 00000000000000000000000000000000 P 8b48d55544984814a74a817e7003247e [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8b48d55544984814a74a817e7003247e" member_type: VOTER }
I20260812 06:16:29.782992 19627 raft_consensus.cc:385] T 00000000000000000000000000000000 P 8b48d55544984814a74a817e7003247e [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:29.783119 19627 raft_consensus.cc:740] T 00000000000000000000000000000000 P 8b48d55544984814a74a817e7003247e [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 8b48d55544984814a74a817e7003247e, State: Initialized, Role: FOLLOWER
I20260812 06:16:29.783387 19627 consensus_queue.cc:260] T 00000000000000000000000000000000 P 8b48d55544984814a74a817e7003247e [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: "8b48d55544984814a74a817e7003247e" member_type: VOTER }
I20260812 06:16:29.783555 19627 raft_consensus.cc:399] T 00000000000000000000000000000000 P 8b48d55544984814a74a817e7003247e [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:29.783608 19627 raft_consensus.cc:493] T 00000000000000000000000000000000 P 8b48d55544984814a74a817e7003247e [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:29.783668 19627 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 8b48d55544984814a74a817e7003247e [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:29.785122 19627 raft_consensus.cc:515] T 00000000000000000000000000000000 P 8b48d55544984814a74a817e7003247e [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8b48d55544984814a74a817e7003247e" member_type: VOTER }
I20260812 06:16:29.785318 19627 leader_election.cc:304] T 00000000000000000000000000000000 P 8b48d55544984814a74a817e7003247e [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: 8b48d55544984814a74a817e7003247e; no voters: 
I20260812 06:16:29.785620 19627 leader_election.cc:290] T 00000000000000000000000000000000 P 8b48d55544984814a74a817e7003247e [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:29.785808 19631 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 8b48d55544984814a74a817e7003247e [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:29.786072 19631 raft_consensus.cc:697] T 00000000000000000000000000000000 P 8b48d55544984814a74a817e7003247e [term 1 LEADER]: Becoming Leader. State: Replica: 8b48d55544984814a74a817e7003247e, State: Running, Role: LEADER
I20260812 06:16:29.786289 19627 sys_catalog.cc:565] T 00000000000000000000000000000000 P 8b48d55544984814a74a817e7003247e [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:29.786255 19631 consensus_queue.cc:237] T 00000000000000000000000000000000 P 8b48d55544984814a74a817e7003247e [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: "8b48d55544984814a74a817e7003247e" member_type: VOTER }
I20260812 06:16:29.786947 19635 sys_catalog.cc:455] T 00000000000000000000000000000000 P 8b48d55544984814a74a817e7003247e [sys.catalog]: SysCatalogTable state changed. Reason: New leader 8b48d55544984814a74a817e7003247e. Latest consensus state: current_term: 1 leader_uuid: "8b48d55544984814a74a817e7003247e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8b48d55544984814a74a817e7003247e" member_type: VOTER } }
I20260812 06:16:29.787038 19635 sys_catalog.cc:458] T 00000000000000000000000000000000 P 8b48d55544984814a74a817e7003247e [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:29.787251 19632 sys_catalog.cc:455] T 00000000000000000000000000000000 P 8b48d55544984814a74a817e7003247e [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "8b48d55544984814a74a817e7003247e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8b48d55544984814a74a817e7003247e" member_type: VOTER } }
I20260812 06:16:29.787441 19632 sys_catalog.cc:458] T 00000000000000000000000000000000 P 8b48d55544984814a74a817e7003247e [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:29.787694 19639 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:29.788458 19639 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:29.788661 19331 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:29.790450 19639 catalog_manager.cc:1383] Generated new cluster ID: 96fd2ae222a94ccda1b5b88f1f353440
I20260812 06:16:29.790537 19639 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:29.797472 19639 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:29.798050 19639 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:29.806692 19639 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 8b48d55544984814a74a817e7003247e: Generated new TSK 0
I20260812 06:16:29.806892 19639 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:29.821527 19331 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:29.823832 19655 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:16:29.823992 19659 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:16:29.824025 19654 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:16:29.824186 19331 server_base.cc:1061] running on GCE node
I20260812 06:16:29.824443 19331 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:29.824486 19331 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:16:29.824503 19331 hybrid_clock.cc:648] HybridClock initialized: now 1786515389824503 us; error 0 us; skew 500 ppm
I20260812 06:16:29.825526 19331 webserver.cc:533] Webserver started at http://127.18.224.193:46155/ using document root <none> and password file <none>
I20260812 06:16:29.825745 19331 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:29.825822 19331 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:29.825915 19331 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:29.826345 19331 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384016249-19331-0/minicluster-data/ts-0-root/instance:
uuid: "d2398a16f1394e7dae1e646332dc82bf"
format_stamp: "Formatted at 2026-08-12 06:16:29 on dist-test-slave-5l3k"
I20260812 06:16:29.828135 19331 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:16:29.829293 19665 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:16:29.829572 19331 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:16:29.829668 19331 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384016249-19331-0/minicluster-data/ts-0-root
uuid: "d2398a16f1394e7dae1e646332dc82bf"
format_stamp: "Formatted at 2026-08-12 06:16:29 on dist-test-slave-5l3k"
I20260812 06:16:29.829768 19331 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384016249-19331-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384016249-19331-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384016249-19331-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:16:29.850805 19331 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:29.851303 19331 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:29.851670 19331 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:29.852202 19331 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:29.852267 19331 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:29.852334 19331 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:29.852388 19331 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:29.858212 19331 rpc_server.cc:307] RPC server started. Bound to: 127.18.224.193:37581
I20260812 06:16:29.859105 19742 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.18.224.193:37581 every 8 connection(s)
I20260812 06:16:29.868530 19743 heartbeater.cc:344] Connected to a master server at 127.18.224.254:42193
I20260812 06:16:29.868695 19743 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:29.868995 19743 heartbeater.cc:507] Master 127.18.224.254:42193 requested a full tablet report, sending...
I20260812 06:16:29.869830 19588 ts_manager.cc:194] Registered new tserver with Master: d2398a16f1394e7dae1e646332dc82bf (127.18.224.193:37581)
I20260812 06:16:29.870162 19331 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011107732s
I20260812 06:16:29.870998 19588 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:41586
I20260812 06:16:29.878273 19588 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:41598:
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:16:29.886945 19701 tablet_service.cc:1511] Processing CreateTablet for tablet c2259c98aa6647e7bb89831f1933df11 (DEFAULT_TABLE table=heavy-update-compaction-test [id=4e5e01a2ec644752a3e232bc6b801ea6]), partition=
I20260812 06:16:29.887337 19701 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet c2259c98aa6647e7bb89831f1933df11. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:29.889343 19758 tablet_bootstrap.cc:492] T c2259c98aa6647e7bb89831f1933df11 P d2398a16f1394e7dae1e646332dc82bf: Bootstrap starting.
I20260812 06:16:29.890460 19758 tablet_bootstrap.cc:654] T c2259c98aa6647e7bb89831f1933df11 P d2398a16f1394e7dae1e646332dc82bf: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:29.891737 19758 tablet_bootstrap.cc:492] T c2259c98aa6647e7bb89831f1933df11 P d2398a16f1394e7dae1e646332dc82bf: No bootstrap required, opened a new log
I20260812 06:16:29.891870 19758 ts_tablet_manager.cc:1403] T c2259c98aa6647e7bb89831f1933df11 P d2398a16f1394e7dae1e646332dc82bf: Time spent bootstrapping tablet: real 0.003s	user 0.000s	sys 0.002s
I20260812 06:16:29.892474 19758 raft_consensus.cc:359] T c2259c98aa6647e7bb89831f1933df11 P d2398a16f1394e7dae1e646332dc82bf [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d2398a16f1394e7dae1e646332dc82bf" member_type: VOTER last_known_addr { host: "127.18.224.193" port: 37581 } }
I20260812 06:16:29.892619 19758 raft_consensus.cc:385] T c2259c98aa6647e7bb89831f1933df11 P d2398a16f1394e7dae1e646332dc82bf [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:29.892656 19758 raft_consensus.cc:740] T c2259c98aa6647e7bb89831f1933df11 P d2398a16f1394e7dae1e646332dc82bf [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: d2398a16f1394e7dae1e646332dc82bf, State: Initialized, Role: FOLLOWER
I20260812 06:16:29.892833 19758 consensus_queue.cc:260] T c2259c98aa6647e7bb89831f1933df11 P d2398a16f1394e7dae1e646332dc82bf [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: "d2398a16f1394e7dae1e646332dc82bf" member_type: VOTER last_known_addr { host: "127.18.224.193" port: 37581 } }
I20260812 06:16:29.892956 19758 raft_consensus.cc:399] T c2259c98aa6647e7bb89831f1933df11 P d2398a16f1394e7dae1e646332dc82bf [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:29.893021 19758 raft_consensus.cc:493] T c2259c98aa6647e7bb89831f1933df11 P d2398a16f1394e7dae1e646332dc82bf [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:29.893090 19758 raft_consensus.cc:3060] T c2259c98aa6647e7bb89831f1933df11 P d2398a16f1394e7dae1e646332dc82bf [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:29.893949 19758 raft_consensus.cc:515] T c2259c98aa6647e7bb89831f1933df11 P d2398a16f1394e7dae1e646332dc82bf [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d2398a16f1394e7dae1e646332dc82bf" member_type: VOTER last_known_addr { host: "127.18.224.193" port: 37581 } }
I20260812 06:16:29.894142 19758 leader_election.cc:304] T c2259c98aa6647e7bb89831f1933df11 P d2398a16f1394e7dae1e646332dc82bf [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: d2398a16f1394e7dae1e646332dc82bf; no voters: 
I20260812 06:16:29.894413 19758 leader_election.cc:290] T c2259c98aa6647e7bb89831f1933df11 P d2398a16f1394e7dae1e646332dc82bf [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:29.894625 19762 raft_consensus.cc:2804] T c2259c98aa6647e7bb89831f1933df11 P d2398a16f1394e7dae1e646332dc82bf [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:29.894896 19758 ts_tablet_manager.cc:1434] T c2259c98aa6647e7bb89831f1933df11 P d2398a16f1394e7dae1e646332dc82bf: Time spent starting tablet: real 0.003s	user 0.000s	sys 0.003s
I20260812 06:16:29.894873 19743 heartbeater.cc:499] Master 127.18.224.254:42193 was elected leader, sending a full tablet report...
I20260812 06:16:29.894879 19762 raft_consensus.cc:697] T c2259c98aa6647e7bb89831f1933df11 P d2398a16f1394e7dae1e646332dc82bf [term 1 LEADER]: Becoming Leader. State: Replica: d2398a16f1394e7dae1e646332dc82bf, State: Running, Role: LEADER
I20260812 06:16:29.895164 19762 consensus_queue.cc:237] T c2259c98aa6647e7bb89831f1933df11 P d2398a16f1394e7dae1e646332dc82bf [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: "d2398a16f1394e7dae1e646332dc82bf" member_type: VOTER last_known_addr { host: "127.18.224.193" port: 37581 } }
I20260812 06:16:29.896807 19588 catalog_manager.cc:5719] T c2259c98aa6647e7bb89831f1933df11 P d2398a16f1394e7dae1e646332dc82bf reported cstate change: term changed from 0 to 1, leader changed from <none> to d2398a16f1394e7dae1e646332dc82bf (127.18.224.193). New cstate: current_term: 1 leader_uuid: "d2398a16f1394e7dae1e646332dc82bf" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d2398a16f1394e7dae1e646332dc82bf" member_type: VOTER last_known_addr { host: "127.18.224.193" port: 37581 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:29.957365 19331 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.054s	user 0.010s	sys 0.012s
I20260812 06:16:30.109747 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling FlushMRSOp(c2259c98aa6647e7bb89831f1933df11): perf score=19.054940
I20260812 06:16:30.265971 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: FlushMRSOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.156s	user 0.098s	sys 0.055s Metrics: {"bytes_written":12307491,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":94,"dirs.run_cpu_time_us":203,"dirs.run_wall_time_us":870,"drs_written":1,"lbm_read_time_us":75,"lbm_reads_lt_1ms":4,"lbm_write_time_us":38623,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":10496,"update_count":1500}
I20260812 06:16:30.266767 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling LogGCOp(c2259c98aa6647e7bb89831f1933df11): free 20743880 bytes of WAL
I20260812 06:16:30.267040 19671 log_reader.cc:385] T c2259c98aa6647e7bb89831f1933df11: removed 2 log segments from log reader
I20260812 06:16:30.267084 19671 log.cc:1079] T c2259c98aa6647e7bb89831f1933df11 P d2398a16f1394e7dae1e646332dc82bf: Deleting log segment in path: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384016249-19331-0/minicluster-data/ts-0-root/wals/c2259c98aa6647e7bb89831f1933df11/wal-000000001 (ops 1-6)
I20260812 06:16:30.267143 19671 log.cc:1079] T c2259c98aa6647e7bb89831f1933df11 P d2398a16f1394e7dae1e646332dc82bf: Deleting log segment in path: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384016249-19331-0/minicluster-data/ts-0-root/wals/c2259c98aa6647e7bb89831f1933df11/wal-000000002 (ops 7-11)
I20260812 06:16:30.271792 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: LogGCOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.005s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:16:30.272293 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11): perf score=2.188937
I20260812 06:16:30.287796 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.015s	user 0.012s	sys 0.002s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5478,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:30.288337 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling UndoDeltaBlockGCOp(c2259c98aa6647e7bb89831f1933df11): 16411392 bytes on disk
I20260812 06:16:30.288978 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: UndoDeltaBlockGCOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":96,"lbm_reads_lt_1ms":4}
I20260812 06:16:30.289440 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling MajorDeltaCompactionOp(c2259c98aa6647e7bb89831f1933df11): perf score=1.000000
I20260812 06:16:30.453446 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: MajorDeltaCompactionOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.164s	user 0.107s	sys 0.056s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":525,"lbm_read_time_us":11530,"lbm_reads_lt_1ms":460,"lbm_write_time_us":26471,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"thread_start_us":371,"threads_started":5,"update_count":2000}
I20260812 06:16:30.453964 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11): perf score=10.126437
I20260812 06:16:30.489742 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.036s	user 0.008s	sys 0.024s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15581,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:30.490339 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11): perf score=2.188937
I20260812 06:16:30.507408 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.017s	user 0.015s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6482,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:30.507977 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling MajorDeltaCompactionOp(c2259c98aa6647e7bb89831f1933df11): perf score=1.000000
I20260812 06:16:30.635749 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: MajorDeltaCompactionOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.128s	user 0.103s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":270,"lbm_read_time_us":8213,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23958,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11392,"update_count":2000}
I20260812 06:16:30.636583 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11): perf score=10.126437
I20260812 06:16:30.673813 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.037s	user 0.016s	sys 0.012s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":13732,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:30.674433 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11): perf score=2.188937
I20260812 06:16:30.685240 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4126,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:30.685772 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling MajorDeltaCompactionOp(c2259c98aa6647e7bb89831f1933df11): perf score=1.000000
I20260812 06:16:30.818825 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: MajorDeltaCompactionOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.133s	user 0.104s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":729,"lbm_read_time_us":9869,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26202,"lbm_writes_lt_1ms":443,"mutex_wait_us":392,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10240,"update_count":2000}
I20260812 06:16:30.819550 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11): perf score=10.126437
I20260812 06:16:30.866086 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.046s	user 0.015s	sys 0.028s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":20008,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:30.866664 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11): perf score=2.188937
I20260812 06:16:30.877836 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4138,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:30.878521 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling MajorDeltaCompactionOp(c2259c98aa6647e7bb89831f1933df11): perf score=1.000000
I20260812 06:16:31.009140 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: MajorDeltaCompactionOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.130s	user 0.094s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":964,"lbm_read_time_us":9413,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23305,"lbm_writes_lt_1ms":443,"mutex_wait_us":353,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3584,"update_count":2000}
I20260812 06:16:31.009791 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11): perf score=10.126437
I20260812 06:16:31.066334 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.056s	user 0.031s	sys 0.021s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19981,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:31.067030 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11): perf score=2.188937
I20260812 06:16:31.078701 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.011s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4632,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:31.079164 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling MajorDeltaCompactionOp(c2259c98aa6647e7bb89831f1933df11): perf score=1.000000
I20260812 06:16:31.228826 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: MajorDeltaCompactionOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.149s	user 0.087s	sys 0.060s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":256,"lbm_read_time_us":11502,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24538,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":26240,"update_count":2000}
I20260812 06:16:31.229460 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11): perf score=10.126437
I20260812 06:16:31.273962 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.044s	user 0.031s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17822,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:31.274456 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11): perf score=2.188937
I20260812 06:16:31.287010 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.012s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4723,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:31.287626 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling MajorDeltaCompactionOp(c2259c98aa6647e7bb89831f1933df11): perf score=1.000000
I20260812 06:16:31.416021 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: MajorDeltaCompactionOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.128s	user 0.096s	sys 0.032s 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":821,"lbm_read_time_us":8725,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23879,"lbm_writes_lt_1ms":443,"mutex_wait_us":331,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":2000}
I20260812 06:16:31.416697 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11): perf score=10.126437
I20260812 06:16:31.456617 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.040s	user 0.023s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15998,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:31.457222 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11): perf score=2.188937
I20260812 06:16:31.473555 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.016s	user 0.006s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6331,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:31.474215 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling FlushMRSOp(c2259c98aa6647e7bb89831f1933df11): perf score=1.000000
I20260812 06:16:31.505501 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: FlushMRSOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.031s	user 0.024s	sys 0.004s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":106,"dirs.run_cpu_time_us":331,"dirs.run_wall_time_us":1537,"drs_written":1,"lbm_read_time_us":41,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1583,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28,"spinlock_wait_cycles":13184}
I20260812 06:16:31.506146 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling LogGCOp(c2259c98aa6647e7bb89831f1933df11): free 112239310 bytes of WAL
I20260812 06:16:31.506392 19671 log_reader.cc:385] T c2259c98aa6647e7bb89831f1933df11: removed 11 log segments from log reader
I20260812 06:16:31.506436 19671 log.cc:1079] T c2259c98aa6647e7bb89831f1933df11 P d2398a16f1394e7dae1e646332dc82bf: Deleting log segment in path: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384016249-19331-0/minicluster-data/ts-0-root/wals/c2259c98aa6647e7bb89831f1933df11/wal-000000003 (ops 12-16)
I20260812 06:16:31.506469 19671 log.cc:1079] T c2259c98aa6647e7bb89831f1933df11 P d2398a16f1394e7dae1e646332dc82bf: Deleting log segment in path: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384016249-19331-0/minicluster-data/ts-0-root/wals/c2259c98aa6647e7bb89831f1933df11/wal-000000004 (ops 17-21)
I20260812 06:16:31.506558 19671 log.cc:1079] T c2259c98aa6647e7bb89831f1933df11 P d2398a16f1394e7dae1e646332dc82bf: Deleting log segment in path: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384016249-19331-0/minicluster-data/ts-0-root/wals/c2259c98aa6647e7bb89831f1933df11/wal-000000005 (ops 22-26)
I20260812 06:16:31.506621 19671 log.cc:1079] T c2259c98aa6647e7bb89831f1933df11 P d2398a16f1394e7dae1e646332dc82bf: Deleting log segment in path: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384016249-19331-0/minicluster-data/ts-0-root/wals/c2259c98aa6647e7bb89831f1933df11/wal-000000006 (ops 27-31)
I20260812 06:16:31.506665 19671 log.cc:1079] T c2259c98aa6647e7bb89831f1933df11 P d2398a16f1394e7dae1e646332dc82bf: Deleting log segment in path: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384016249-19331-0/minicluster-data/ts-0-root/wals/c2259c98aa6647e7bb89831f1933df11/wal-000000007 (ops 32-36)
I20260812 06:16:31.506692 19671 log.cc:1079] T c2259c98aa6647e7bb89831f1933df11 P d2398a16f1394e7dae1e646332dc82bf: Deleting log segment in path: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384016249-19331-0/minicluster-data/ts-0-root/wals/c2259c98aa6647e7bb89831f1933df11/wal-000000008 (ops 37-41)
I20260812 06:16:31.506734 19671 log.cc:1079] T c2259c98aa6647e7bb89831f1933df11 P d2398a16f1394e7dae1e646332dc82bf: Deleting log segment in path: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384016249-19331-0/minicluster-data/ts-0-root/wals/c2259c98aa6647e7bb89831f1933df11/wal-000000009 (ops 42-46)
I20260812 06:16:31.506774 19671 log.cc:1079] T c2259c98aa6647e7bb89831f1933df11 P d2398a16f1394e7dae1e646332dc82bf: Deleting log segment in path: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384016249-19331-0/minicluster-data/ts-0-root/wals/c2259c98aa6647e7bb89831f1933df11/wal-000000010 (ops 47-51)
I20260812 06:16:31.506815 19671 log.cc:1079] T c2259c98aa6647e7bb89831f1933df11 P d2398a16f1394e7dae1e646332dc82bf: Deleting log segment in path: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384016249-19331-0/minicluster-data/ts-0-root/wals/c2259c98aa6647e7bb89831f1933df11/wal-000000011 (ops 52-56)
I20260812 06:16:31.506853 19671 log.cc:1079] T c2259c98aa6647e7bb89831f1933df11 P d2398a16f1394e7dae1e646332dc82bf: Deleting log segment in path: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384016249-19331-0/minicluster-data/ts-0-root/wals/c2259c98aa6647e7bb89831f1933df11/wal-000000012 (ops 57-60)
I20260812 06:16:31.506894 19671 log.cc:1079] T c2259c98aa6647e7bb89831f1933df11 P d2398a16f1394e7dae1e646332dc82bf: Deleting log segment in path: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384016249-19331-0/minicluster-data/ts-0-root/wals/c2259c98aa6647e7bb89831f1933df11/wal-000000013 (ops 61-65)
I20260812 06:16:31.530874 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: LogGCOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.024s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:16:31.531351 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling UndoDeltaBlockGCOp(c2259c98aa6647e7bb89831f1933df11): 447 bytes on disk
I20260812 06:16:31.531876 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: UndoDeltaBlockGCOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4}
I20260812 06:16:31.532394 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11): perf score=3.181125
I20260812 06:16:31.553380 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.021s	user 0.014s	sys 0.002s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":7010,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:31.553928 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11): perf score=2.188937
I20260812 06:16:31.563896 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3618,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:31.564406 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling MajorDeltaCompactionOp(c2259c98aa6647e7bb89831f1933df11): perf score=1.000000
I20260812 06:16:31.741400 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: MajorDeltaCompactionOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.177s	user 0.143s	sys 0.031s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877328,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":789,"lbm_read_time_us":12245,"lbm_reads_lt_1ms":674,"lbm_write_time_us":36155,"lbm_writes_lt_1ms":643,"mutex_wait_us":73,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2048,"thread_start_us":78,"threads_started":1,"update_count":3000}
I20260812 06:16:31.742048 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11): perf score=14.095187
I20260812 06:16:31.796767 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.054s	user 0.033s	sys 0.019s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":25781,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:16:31.797268 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11): perf score=2.188937
I20260812 06:16:31.809818 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4881,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:31.810300 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling MajorDeltaCompactionOp(c2259c98aa6647e7bb89831f1933df11): perf score=1.000000
I20260812 06:16:31.981576 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: MajorDeltaCompactionOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.171s	user 0.144s	sys 0.024s 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":152,"lbm_read_time_us":14090,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33834,"lbm_writes_lt_1ms":543,"mutex_wait_us":34,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":31616,"update_count":2500}
I20260812 06:16:31.982120 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11): perf score=10.126437
I20260812 06:16:32.022949 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.041s	user 0.030s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16108,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:32.023489 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling MajorDeltaCompactionOp(c2259c98aa6647e7bb89831f1933df11): perf score=1.000000
I20260812 06:16:32.140576 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: MajorDeltaCompactionOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.114s	user 0.103s	sys 0.011s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569746,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1021,"lbm_read_time_us":5995,"lbm_reads_lt_1ms":363,"lbm_write_time_us":24116,"lbm_writes_lt_1ms":343,"mutex_wait_us":326,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":20224,"update_count":1500}
I20260812 06:16:32.141302 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11): perf score=6.157687
I20260812 06:16:32.175482 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.034s	user 0.024s	sys 0.008s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":13569,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:32.176205 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11): perf score=2.188937
I20260812 06:16:32.198971 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.023s	user 0.018s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6967,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:32.199647 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling MajorDeltaCompactionOp(c2259c98aa6647e7bb89831f1933df11): perf score=1.000000
I20260812 06:16:32.321976 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: MajorDeltaCompactionOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.122s	user 0.100s	sys 0.020s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16569865,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":2106,"lbm_read_time_us":8121,"lbm_reads_lt_1ms":364,"lbm_write_time_us":21245,"lbm_writes_lt_1ms":343,"mutex_wait_us":1319,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":3840,"update_count":1500}
I20260812 06:16:32.322841 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11): perf score=6.157687
I20260812 06:16:32.363354 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.040s	user 0.018s	sys 0.008s Metrics: {"bytes_written":8205077,"delete_count":0,"lbm_write_time_us":11769,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:32.363906 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11): perf score=2.188937
I20260812 06:16:32.375133 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4150,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:32.375957 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling MajorDeltaCompactionOp(c2259c98aa6647e7bb89831f1933df11): perf score=1.000000
I20260812 06:16:32.489503 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: MajorDeltaCompactionOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.113s	user 0.099s	sys 0.011s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16569864,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":304,"lbm_read_time_us":7855,"lbm_reads_lt_1ms":372,"lbm_write_time_us":19854,"lbm_writes_lt_1ms":343,"mutex_wait_us":72,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":7936,"update_count":1500}
I20260812 06:16:32.490008 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11): perf score=7.149875
I20260812 06:16:32.516716 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.027s	user 0.020s	sys 0.004s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":11507,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:16:32.517220 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11): perf score=2.188937
I20260812 06:16:32.528004 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.011s	user 0.008s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3790,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:32.528471 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling MajorDeltaCompactionOp(c2259c98aa6647e7bb89831f1933df11): perf score=1.000000
I20260812 06:16:32.644497 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: MajorDeltaCompactionOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.116s	user 0.087s	sys 0.019s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16569856,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":431,"lbm_read_time_us":6156,"lbm_reads_lt_1ms":372,"lbm_write_time_us":21113,"lbm_writes_lt_1ms":343,"mutex_wait_us":56,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":3584,"update_count":1500}
I20260812 06:16:32.645220 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11): perf score=10.126437
I20260812 06:16:32.679705 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.034s	user 0.013s	sys 0.019s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14470,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:32.680207 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling MajorDeltaCompactionOp(c2259c98aa6647e7bb89831f1933df11): perf score=1.000000
I20260812 06:16:32.790068 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: MajorDeltaCompactionOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.110s	user 0.081s	sys 0.028s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569747,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":878,"lbm_read_time_us":6228,"lbm_reads_lt_1ms":363,"lbm_write_time_us":21891,"lbm_writes_lt_1ms":343,"mutex_wait_us":277,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":12032,"update_count":1500}
I20260812 06:16:32.790967 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11): perf score=10.126437
I20260812 06:16:32.835395 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.044s	user 0.013s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16048,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:32.836020 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11): perf score=2.188937
I20260812 06:16:32.847290 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3940,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:32.848042 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling MajorDeltaCompactionOp(c2259c98aa6647e7bb89831f1933df11): perf score=1.000000
I20260812 06:16:32.989534 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: MajorDeltaCompactionOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.141s	user 0.113s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1048,"lbm_read_time_us":8511,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26433,"lbm_writes_lt_1ms":443,"mutex_wait_us":321,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":74368,"update_count":2000}
I20260812 06:16:32.990427 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11): perf score=10.126437
I20260812 06:16:33.030661 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.040s	user 0.020s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16241,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:33.031167 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11): perf score=2.188937
I20260812 06:16:33.051355 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.020s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5298,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:33.052022 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling FlushMRSOp(c2259c98aa6647e7bb89831f1933df11): perf score=1.000000
I20260812 06:16:33.105278 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: FlushMRSOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.053s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":67,"dirs.run_cpu_time_us":294,"dirs.run_wall_time_us":1854,"drs_written":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2155,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:16:33.106079 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling LogGCOp(c2259c98aa6647e7bb89831f1933df11): free 120553331 bytes of WAL
I20260812 06:16:33.106374 19671 log_reader.cc:385] T c2259c98aa6647e7bb89831f1933df11: removed 12 log segments from log reader
I20260812 06:16:33.106424 19671 log.cc:1079] T c2259c98aa6647e7bb89831f1933df11 P d2398a16f1394e7dae1e646332dc82bf: Deleting log segment in path: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384016249-19331-0/minicluster-data/ts-0-root/wals/c2259c98aa6647e7bb89831f1933df11/wal-000000014 (ops 66-70)
I20260812 06:16:33.106454 19671 log.cc:1079] T c2259c98aa6647e7bb89831f1933df11 P d2398a16f1394e7dae1e646332dc82bf: Deleting log segment in path: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384016249-19331-0/minicluster-data/ts-0-root/wals/c2259c98aa6647e7bb89831f1933df11/wal-000000015 (ops 71-74)
I20260812 06:16:33.106544 19671 log.cc:1079] T c2259c98aa6647e7bb89831f1933df11 P d2398a16f1394e7dae1e646332dc82bf: Deleting log segment in path: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384016249-19331-0/minicluster-data/ts-0-root/wals/c2259c98aa6647e7bb89831f1933df11/wal-000000016 (ops 75-79)
I20260812 06:16:33.106596 19671 log.cc:1079] T c2259c98aa6647e7bb89831f1933df11 P d2398a16f1394e7dae1e646332dc82bf: Deleting log segment in path: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384016249-19331-0/minicluster-data/ts-0-root/wals/c2259c98aa6647e7bb89831f1933df11/wal-000000017 (ops 80-84)
I20260812 06:16:33.106637 19671 log.cc:1079] T c2259c98aa6647e7bb89831f1933df11 P d2398a16f1394e7dae1e646332dc82bf: Deleting log segment in path: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384016249-19331-0/minicluster-data/ts-0-root/wals/c2259c98aa6647e7bb89831f1933df11/wal-000000018 (ops 85-89)
I20260812 06:16:33.106707 19671 log.cc:1079] T c2259c98aa6647e7bb89831f1933df11 P d2398a16f1394e7dae1e646332dc82bf: Deleting log segment in path: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384016249-19331-0/minicluster-data/ts-0-root/wals/c2259c98aa6647e7bb89831f1933df11/wal-000000019 (ops 90-94)
I20260812 06:16:33.106750 19671 log.cc:1079] T c2259c98aa6647e7bb89831f1933df11 P d2398a16f1394e7dae1e646332dc82bf: Deleting log segment in path: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384016249-19331-0/minicluster-data/ts-0-root/wals/c2259c98aa6647e7bb89831f1933df11/wal-000000020 (ops 95-99)
I20260812 06:16:33.106791 19671 log.cc:1079] T c2259c98aa6647e7bb89831f1933df11 P d2398a16f1394e7dae1e646332dc82bf: Deleting log segment in path: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384016249-19331-0/minicluster-data/ts-0-root/wals/c2259c98aa6647e7bb89831f1933df11/wal-000000021 (ops 100-104)
I20260812 06:16:33.106828 19671 log.cc:1079] T c2259c98aa6647e7bb89831f1933df11 P d2398a16f1394e7dae1e646332dc82bf: Deleting log segment in path: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384016249-19331-0/minicluster-data/ts-0-root/wals/c2259c98aa6647e7bb89831f1933df11/wal-000000022 (ops 105-109)
I20260812 06:16:33.106865 19671 log.cc:1079] T c2259c98aa6647e7bb89831f1933df11 P d2398a16f1394e7dae1e646332dc82bf: Deleting log segment in path: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384016249-19331-0/minicluster-data/ts-0-root/wals/c2259c98aa6647e7bb89831f1933df11/wal-000000023 (ops 110-114)
I20260812 06:16:33.106904 19671 log.cc:1079] T c2259c98aa6647e7bb89831f1933df11 P d2398a16f1394e7dae1e646332dc82bf: Deleting log segment in path: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384016249-19331-0/minicluster-data/ts-0-root/wals/c2259c98aa6647e7bb89831f1933df11/wal-000000024 (ops 115-118)
I20260812 06:16:33.106941 19671 log.cc:1079] T c2259c98aa6647e7bb89831f1933df11 P d2398a16f1394e7dae1e646332dc82bf: Deleting log segment in path: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384016249-19331-0/minicluster-data/ts-0-root/wals/c2259c98aa6647e7bb89831f1933df11/wal-000000025 (ops 119-123)
I20260812 06:16:33.133458 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: LogGCOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.027s	user 0.001s	sys 0.023s Metrics: {}
I20260812 06:16:33.133912 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling UndoDeltaBlockGCOp(c2259c98aa6647e7bb89831f1933df11): 483 bytes on disk
I20260812 06:16:33.134408 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: UndoDeltaBlockGCOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4}
I20260812 06:16:33.134954 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11): perf score=6.157687
I20260812 06:16:33.163605 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.028s	user 0.024s	sys 0.004s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":12309,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:33.164175 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling LogGCOp(c2259c98aa6647e7bb89831f1933df11): free 8767174 bytes of WAL
I20260812 06:16:33.164397 19671 log_reader.cc:385] T c2259c98aa6647e7bb89831f1933df11: removed 1 log segments from log reader
I20260812 06:16:33.164438 19671 log.cc:1079] T c2259c98aa6647e7bb89831f1933df11 P d2398a16f1394e7dae1e646332dc82bf: Deleting log segment in path: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384016249-19331-0/minicluster-data/ts-0-root/wals/c2259c98aa6647e7bb89831f1933df11/wal-000000026 (ops 124-128)
I20260812 06:16:33.166221 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: LogGCOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:16:33.166630 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11): perf score=2.188937
I20260812 06:16:33.179248 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.012s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4735,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:33.179706 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling MajorDeltaCompactionOp(c2259c98aa6647e7bb89831f1933df11): perf score=1.000000
I20260812 06:16:33.417977 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: MajorDeltaCompactionOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.238s	user 0.137s	sys 0.088s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979751,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":170,"lbm_read_time_us":12464,"lbm_reads_lt_1ms":774,"lbm_write_time_us":42260,"lbm_writes_lt_1ms":743,"mutex_wait_us":23,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":12416,"thread_start_us":79,"threads_started":1,"update_count":3500}
I20260812 06:16:33.419085 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11): perf score=18.063937
I20260812 06:16:33.485635 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.066s	user 0.043s	sys 0.020s Metrics: {"bytes_written":20512318,"delete_count":0,"lbm_write_time_us":24519,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:16:33.486214 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11): perf score=2.188937
I20260812 06:16:33.498870 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.012s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4473,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:33.499548 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling MajorDeltaCompactionOp(c2259c98aa6647e7bb89831f1933df11): perf score=1.000000
I20260812 06:16:33.701704 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: MajorDeltaCompactionOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.202s	user 0.129s	sys 0.072s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877104,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":2744,"lbm_read_time_us":15055,"lbm_reads_lt_1ms":672,"lbm_write_time_us":33975,"lbm_writes_lt_1ms":643,"mutex_wait_us":701,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":3000}
I20260812 06:16:33.702461 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11): perf score=14.095187
I20260812 06:16:33.755548 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.053s	user 0.035s	sys 0.017s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22945,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:33.756326 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11): perf score=2.188937
I20260812 06:16:33.774595 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.018s	user 0.015s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7047,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:33.775125 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling MajorDeltaCompactionOp(c2259c98aa6647e7bb89831f1933df11): perf score=1.000000
I20260812 06:16:33.954922 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: MajorDeltaCompactionOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.180s	user 0.107s	sys 0.073s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1007,"lbm_read_time_us":13329,"lbm_reads_lt_1ms":568,"lbm_write_time_us":30979,"lbm_writes_lt_1ms":543,"mutex_wait_us":111,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":18048,"update_count":2500}
I20260812 06:16:33.955747 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11): perf score=14.095187
I20260812 06:16:34.014418 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.058s	user 0.031s	sys 0.024s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21017,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:34.015161 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11): perf score=2.188937
I20260812 06:16:34.091560 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.076s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4203,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:34.092231 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling MajorDeltaCompactionOp(c2259c98aa6647e7bb89831f1933df11): perf score=1.000000
I20260812 06:16:34.265941 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: MajorDeltaCompactionOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.174s	user 0.119s	sys 0.051s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":296,"lbm_read_time_us":10671,"lbm_reads_lt_1ms":564,"lbm_write_time_us":28348,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":22144,"update_count":2500}
I20260812 06:16:34.266554 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11): perf score=14.095187
I20260812 06:16:34.322669 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.056s	user 0.034s	sys 0.021s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24667,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:34.323236 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11): perf score=2.188937
I20260812 06:16:34.344415 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.021s	user 0.009s	sys 0.010s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3998,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:34.345135 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling MajorDeltaCompactionOp(c2259c98aa6647e7bb89831f1933df11): perf score=1.000000
I20260812 06:16:34.544164 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: MajorDeltaCompactionOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.199s	user 0.126s	sys 0.070s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":101,"lbm_read_time_us":14947,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30913,"lbm_writes_lt_1ms":543,"mutex_wait_us":50,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":15872,"update_count":2500}
I20260812 06:16:34.544872 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11): perf score=11.118625
I20260812 06:16:34.579535 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.034s	user 0.021s	sys 0.012s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14977,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:34.580111 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11): perf score=2.188937
I20260812 06:16:34.604192 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.022s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5424,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:34.604797 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11): perf score=2.188937
I20260812 06:16:34.616401 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.011s	user 0.007s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4126,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:34.617225 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling FlushMRSOp(c2259c98aa6647e7bb89831f1933df11): perf score=1.000000
I20260812 06:16:34.660535 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: FlushMRSOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.043s	user 0.025s	sys 0.003s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":65,"dirs.run_cpu_time_us":258,"dirs.run_wall_time_us":1384,"drs_written":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2269,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:16:34.661465 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling LogGCOp(c2259c98aa6647e7bb89831f1933df11): free 111786491 bytes of WAL
I20260812 06:16:34.661770 19671 log_reader.cc:385] T c2259c98aa6647e7bb89831f1933df11: removed 11 log segments from log reader
I20260812 06:16:34.661849 19671 log.cc:1079] T c2259c98aa6647e7bb89831f1933df11 P d2398a16f1394e7dae1e646332dc82bf: Deleting log segment in path: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384016249-19331-0/minicluster-data/ts-0-root/wals/c2259c98aa6647e7bb89831f1933df11/wal-000000027 (ops 129-132)
I20260812 06:16:34.661904 19671 log.cc:1079] T c2259c98aa6647e7bb89831f1933df11 P d2398a16f1394e7dae1e646332dc82bf: Deleting log segment in path: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384016249-19331-0/minicluster-data/ts-0-root/wals/c2259c98aa6647e7bb89831f1933df11/wal-000000028 (ops 133-137)
I20260812 06:16:34.661963 19671 log.cc:1079] T c2259c98aa6647e7bb89831f1933df11 P d2398a16f1394e7dae1e646332dc82bf: Deleting log segment in path: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384016249-19331-0/minicluster-data/ts-0-root/wals/c2259c98aa6647e7bb89831f1933df11/wal-000000029 (ops 138-142)
I20260812 06:16:34.662005 19671 log.cc:1079] T c2259c98aa6647e7bb89831f1933df11 P d2398a16f1394e7dae1e646332dc82bf: Deleting log segment in path: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384016249-19331-0/minicluster-data/ts-0-root/wals/c2259c98aa6647e7bb89831f1933df11/wal-000000030 (ops 143-147)
I20260812 06:16:34.662041 19671 log.cc:1079] T c2259c98aa6647e7bb89831f1933df11 P d2398a16f1394e7dae1e646332dc82bf: Deleting log segment in path: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384016249-19331-0/minicluster-data/ts-0-root/wals/c2259c98aa6647e7bb89831f1933df11/wal-000000031 (ops 148-152)
I20260812 06:16:34.662073 19671 log.cc:1079] T c2259c98aa6647e7bb89831f1933df11 P d2398a16f1394e7dae1e646332dc82bf: Deleting log segment in path: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384016249-19331-0/minicluster-data/ts-0-root/wals/c2259c98aa6647e7bb89831f1933df11/wal-000000032 (ops 153-157)
I20260812 06:16:34.662096 19671 log.cc:1079] T c2259c98aa6647e7bb89831f1933df11 P d2398a16f1394e7dae1e646332dc82bf: Deleting log segment in path: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384016249-19331-0/minicluster-data/ts-0-root/wals/c2259c98aa6647e7bb89831f1933df11/wal-000000033 (ops 158-162)
I20260812 06:16:34.662125 19671 log.cc:1079] T c2259c98aa6647e7bb89831f1933df11 P d2398a16f1394e7dae1e646332dc82bf: Deleting log segment in path: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384016249-19331-0/minicluster-data/ts-0-root/wals/c2259c98aa6647e7bb89831f1933df11/wal-000000034 (ops 163-167)
I20260812 06:16:34.662168 19671 log.cc:1079] T c2259c98aa6647e7bb89831f1933df11 P d2398a16f1394e7dae1e646332dc82bf: Deleting log segment in path: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384016249-19331-0/minicluster-data/ts-0-root/wals/c2259c98aa6647e7bb89831f1933df11/wal-000000035 (ops 168-172)
I20260812 06:16:34.662204 19671 log.cc:1079] T c2259c98aa6647e7bb89831f1933df11 P d2398a16f1394e7dae1e646332dc82bf: Deleting log segment in path: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384016249-19331-0/minicluster-data/ts-0-root/wals/c2259c98aa6647e7bb89831f1933df11/wal-000000036 (ops 173-176)
I20260812 06:16:34.662240 19671 log.cc:1079] T c2259c98aa6647e7bb89831f1933df11 P d2398a16f1394e7dae1e646332dc82bf: Deleting log segment in path: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384016249-19331-0/minicluster-data/ts-0-root/wals/c2259c98aa6647e7bb89831f1933df11/wal-000000037 (ops 177-181)
I20260812 06:16:34.686628 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: LogGCOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.025s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:16:34.687264 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling UndoDeltaBlockGCOp(c2259c98aa6647e7bb89831f1933df11): 447 bytes on disk
I20260812 06:16:34.687999 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: UndoDeltaBlockGCOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.001s	user 0.000s	sys 0.001s Metrics: {"cfile_init":1,"lbm_read_time_us":102,"lbm_reads_lt_1ms":4}
I20260812 06:16:34.688688 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11): perf score=2.188937
I20260812 06:16:34.714184 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.025s	user 0.002s	sys 0.013s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6253,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:34.714856 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling LogGCOp(c2259c98aa6647e7bb89831f1933df11): free 12017954 bytes of WAL
I20260812 06:16:34.715171 19671 log_reader.cc:385] T c2259c98aa6647e7bb89831f1933df11: removed 1 log segments from log reader
I20260812 06:16:34.715252 19671 log.cc:1079] T c2259c98aa6647e7bb89831f1933df11 P d2398a16f1394e7dae1e646332dc82bf: Deleting log segment in path: /tmp/dist-test-task9uerVH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384016249-19331-0/minicluster-data/ts-0-root/wals/c2259c98aa6647e7bb89831f1933df11/wal-000000038 (ops 182-186)
I20260812 06:16:34.717605 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: LogGCOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:16:34.718271 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11): perf score=2.188937
I20260812 06:16:34.730902 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.012s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4145,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:34.731594 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling MajorDeltaCompactionOp(c2259c98aa6647e7bb89831f1933df11): perf score=1.000000
I20260812 06:16:34.992957 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: MajorDeltaCompactionOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.261s	user 0.169s	sys 0.083s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979861,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":539,"lbm_read_time_us":17680,"lbm_reads_lt_1ms":775,"lbm_write_time_us":41481,"lbm_writes_lt_1ms":743,"mutex_wait_us":46,"peak_mem_usage":87969044,"reinsert_count":0,"thread_start_us":87,"threads_started":1,"update_count":3500}
I20260812 06:16:34.993902 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11): perf score=18.063937
I20260812 06:16:35.067978 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.071s	user 0.046s	sys 0.016s Metrics: {"bytes_written":20512320,"delete_count":0,"lbm_write_time_us":28180,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:16:35.068538 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11): perf score=2.188937
I20260812 06:16:35.079427 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: FlushDeltaMemStoresOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.011s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4025,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:35.079913 19744 maintenance_manager.cc:419] P d2398a16f1394e7dae1e646332dc82bf: Scheduling MajorDeltaCompactionOp(c2259c98aa6647e7bb89831f1933df11): perf score=1.000000
I20260812 06:16:35.114879 19331 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.157s	user 1.881s	sys 0.177s
I20260812 06:16:35.190368 19331 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.075s	user 0.001s	sys 0.000s
I20260812 06:16:35.190959 19331 tablet_server.cc:179] TabletServer@127.18.224.193:0 shutting down...
I20260812 06:16:35.250180 19671 maintenance_manager.cc:643] P d2398a16f1394e7dae1e646332dc82bf: MajorDeltaCompactionOp(c2259c98aa6647e7bb89831f1933df11) complete. Timing: real 0.170s	user 0.128s	sys 0.042s 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":441,"lbm_read_time_us":14818,"lbm_reads_lt_1ms":668,"lbm_write_time_us":29695,"lbm_writes_lt_1ms":643,"mutex_wait_us":50,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":8576,"update_count":3000}
I20260812 06:16:35.250928 19331 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:16:35.251332 19331 tablet_replica.cc:333] T c2259c98aa6647e7bb89831f1933df11 P d2398a16f1394e7dae1e646332dc82bf: stopping tablet replica
I20260812 06:16:35.251495 19331 raft_consensus.cc:2243] T c2259c98aa6647e7bb89831f1933df11 P d2398a16f1394e7dae1e646332dc82bf [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:35.251683 19331 raft_consensus.cc:2272] T c2259c98aa6647e7bb89831f1933df11 P d2398a16f1394e7dae1e646332dc82bf [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:35.268074 19331 tablet_server.cc:196] TabletServer@127.18.224.193:0 shutdown complete.
I20260812 06:16:35.303390 19331 master.cc:562] Master@127.18.224.254:42193 shutting down...
I20260812 06:16:35.307574 19331 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 8b48d55544984814a74a817e7003247e [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:35.307807 19331 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 8b48d55544984814a74a817e7003247e [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:35.307891 19331 tablet_replica.cc:333] T 00000000000000000000000000000000 P 8b48d55544984814a74a817e7003247e: stopping tablet replica
I20260812 06:16:35.321851 19331 master.cc:584] Master@127.18.224.254:42193 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5691 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11388 ms total)

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