[==========] 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:38.962883 21330 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.20.212.190:43697
I20260812 06:16:38.963940 21330 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:38.964598 21330 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:38.971274 21339 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:38.971349 21341 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:38.971369 21330 server_base.cc:1061] running on GCE node
W20260812 06:16:38.971484 21349 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:38.972146 21330 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:38.972270 21330 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:38.972335 21330 hybrid_clock.cc:648] HybridClock initialized: now 1786515398972332 us; error 0 us; skew 500 ppm
I20260812 06:16:38.974154 21330 webserver.cc:533] Webserver started at http://127.20.212.190:44725/ using document root <none> and password file <none>
I20260812 06:16:38.974736 21330 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:38.974825 21330 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:38.975067 21330 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:38.976835 21330 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398952044-21330-0/minicluster-data/master-0-root/instance:
uuid: "0dac71499d65473891d61d933fe12b11"
format_stamp: "Formatted at 2026-08-12 06:16:38 on dist-test-slave-t3q3"
I20260812 06:16:38.980346 21330 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.004s	sys 0.000s
I20260812 06:16:38.982451 21364 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:38.983475 21330 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:16:38.983606 21330 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398952044-21330-0/minicluster-data/master-0-root
uuid: "0dac71499d65473891d61d933fe12b11"
format_stamp: "Formatted at 2026-08-12 06:16:38 on dist-test-slave-t3q3"
I20260812 06:16:38.983716 21330 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398952044-21330-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398952044-21330-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398952044-21330-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:38.999709 21330 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:39.000453 21330 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:39.000643 21330 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:39.008610 21330 rpc_server.cc:307] RPC server started. Bound to: 127.20.212.190:43697
I20260812 06:16:39.008611 21445 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.20.212.190:43697 every 8 connection(s)
I20260812 06:16:39.011015 21448 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:39.016588 21448 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 0dac71499d65473891d61d933fe12b11: Bootstrap starting.
I20260812 06:16:39.019030 21448 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 0dac71499d65473891d61d933fe12b11: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:39.019995 21448 log.cc:826] T 00000000000000000000000000000000 P 0dac71499d65473891d61d933fe12b11: Log is configured to *not* fsync() on all Append() calls
I20260812 06:16:39.021871 21448 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 0dac71499d65473891d61d933fe12b11: No bootstrap required, opened a new log
I20260812 06:16:39.024787 21448 raft_consensus.cc:359] T 00000000000000000000000000000000 P 0dac71499d65473891d61d933fe12b11 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0dac71499d65473891d61d933fe12b11" member_type: VOTER }
I20260812 06:16:39.025007 21448 raft_consensus.cc:385] T 00000000000000000000000000000000 P 0dac71499d65473891d61d933fe12b11 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:39.025127 21448 raft_consensus.cc:740] T 00000000000000000000000000000000 P 0dac71499d65473891d61d933fe12b11 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 0dac71499d65473891d61d933fe12b11, State: Initialized, Role: FOLLOWER
I20260812 06:16:39.025836 21448 consensus_queue.cc:260] T 00000000000000000000000000000000 P 0dac71499d65473891d61d933fe12b11 [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: "0dac71499d65473891d61d933fe12b11" member_type: VOTER }
I20260812 06:16:39.026029 21448 raft_consensus.cc:399] T 00000000000000000000000000000000 P 0dac71499d65473891d61d933fe12b11 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:39.026103 21448 raft_consensus.cc:493] T 00000000000000000000000000000000 P 0dac71499d65473891d61d933fe12b11 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:39.026270 21448 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 0dac71499d65473891d61d933fe12b11 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:39.027135 21448 raft_consensus.cc:515] T 00000000000000000000000000000000 P 0dac71499d65473891d61d933fe12b11 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0dac71499d65473891d61d933fe12b11" member_type: VOTER }
I20260812 06:16:39.027617 21448 leader_election.cc:304] T 00000000000000000000000000000000 P 0dac71499d65473891d61d933fe12b11 [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: 0dac71499d65473891d61d933fe12b11; no voters: 
I20260812 06:16:39.027995 21448 leader_election.cc:290] T 00000000000000000000000000000000 P 0dac71499d65473891d61d933fe12b11 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:39.028156 21451 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 0dac71499d65473891d61d933fe12b11 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:39.028430 21451 raft_consensus.cc:697] T 00000000000000000000000000000000 P 0dac71499d65473891d61d933fe12b11 [term 1 LEADER]: Becoming Leader. State: Replica: 0dac71499d65473891d61d933fe12b11, State: Running, Role: LEADER
I20260812 06:16:39.028855 21451 consensus_queue.cc:237] T 00000000000000000000000000000000 P 0dac71499d65473891d61d933fe12b11 [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: "0dac71499d65473891d61d933fe12b11" member_type: VOTER }
I20260812 06:16:39.029171 21448 sys_catalog.cc:565] T 00000000000000000000000000000000 P 0dac71499d65473891d61d933fe12b11 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:39.030849 21453 sys_catalog.cc:455] T 00000000000000000000000000000000 P 0dac71499d65473891d61d933fe12b11 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "0dac71499d65473891d61d933fe12b11" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0dac71499d65473891d61d933fe12b11" member_type: VOTER } }
I20260812 06:16:39.030886 21454 sys_catalog.cc:455] T 00000000000000000000000000000000 P 0dac71499d65473891d61d933fe12b11 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 0dac71499d65473891d61d933fe12b11. Latest consensus state: current_term: 1 leader_uuid: "0dac71499d65473891d61d933fe12b11" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0dac71499d65473891d61d933fe12b11" member_type: VOTER } }
I20260812 06:16:39.030977 21453 sys_catalog.cc:458] T 00000000000000000000000000000000 P 0dac71499d65473891d61d933fe12b11 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:39.030988 21454 sys_catalog.cc:458] T 00000000000000000000000000000000 P 0dac71499d65473891d61d933fe12b11 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:39.031533 21470 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:39.031750 21330 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:39.033912 21470 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:39.038472 21470 catalog_manager.cc:1383] Generated new cluster ID: 83d9d14b1d224fad945574ac2f4f1c78
I20260812 06:16:39.038539 21470 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:39.052374 21470 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:39.053530 21470 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:39.062327 21470 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 0dac71499d65473891d61d933fe12b11: Generated new TSK 0
I20260812 06:16:39.063068 21470 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:39.064692 21330 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:39.067436 21488 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:39.067502 21486 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:39.067585 21330 server_base.cc:1061] running on GCE node
W20260812 06:16:39.067795 21490 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:39.068090 21330 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:39.068151 21330 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:39.068176 21330 hybrid_clock.cc:648] HybridClock initialized: now 1786515399068176 us; error 0 us; skew 500 ppm
I20260812 06:16:39.069139 21330 webserver.cc:533] Webserver started at http://127.20.212.129:38325/ using document root <none> and password file <none>
I20260812 06:16:39.069303 21330 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:39.069363 21330 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:39.069438 21330 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:39.069871 21330 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398952044-21330-0/minicluster-data/ts-0-root/instance:
uuid: "21c967063a594d03b8a97db00e816f2e"
format_stamp: "Formatted at 2026-08-12 06:16:39 on dist-test-slave-t3q3"
I20260812 06:16:39.071723 21330 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:16:39.072944 21498 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:39.073285 21330 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:39.073350 21330 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398952044-21330-0/minicluster-data/ts-0-root
uuid: "21c967063a594d03b8a97db00e816f2e"
format_stamp: "Formatted at 2026-08-12 06:16:39 on dist-test-slave-t3q3"
I20260812 06:16:39.073438 21330 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398952044-21330-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398952044-21330-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398952044-21330-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:39.078462 21330 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:39.078881 21330 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:39.079332 21330 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:39.080216 21330 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:39.080269 21330 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:39.080334 21330 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:39.080374 21330 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:39.087222 21330 rpc_server.cc:307] RPC server started. Bound to: 127.20.212.129:33489
I20260812 06:16:39.087283 21596 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.20.212.129:33489 every 8 connection(s)
I20260812 06:16:39.097688 21598 heartbeater.cc:344] Connected to a master server at 127.20.212.190:43697
I20260812 06:16:39.097944 21598 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:39.098428 21598 heartbeater.cc:507] Master 127.20.212.190:43697 requested a full tablet report, sending...
I20260812 06:16:39.099885 21393 ts_manager.cc:194] Registered new tserver with Master: 21c967063a594d03b8a97db00e816f2e (127.20.212.129:33489)
I20260812 06:16:39.100139 21330 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012283672s
I20260812 06:16:39.101505 21393 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:33866
I20260812 06:16:39.109829 21393 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:33882:
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:39.124096 21542 tablet_service.cc:1511] Processing CreateTablet for tablet 61bd6cce54da4506baee46ff78d25263 (DEFAULT_TABLE table=heavy-update-compaction-test [id=310d9bff05924dc58378d073ff155ae8]), partition=
I20260812 06:16:39.124538 21542 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 61bd6cce54da4506baee46ff78d25263. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:39.126766 21616 tablet_bootstrap.cc:492] T 61bd6cce54da4506baee46ff78d25263 P 21c967063a594d03b8a97db00e816f2e: Bootstrap starting.
I20260812 06:16:39.127902 21616 tablet_bootstrap.cc:654] T 61bd6cce54da4506baee46ff78d25263 P 21c967063a594d03b8a97db00e816f2e: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:39.129279 21616 tablet_bootstrap.cc:492] T 61bd6cce54da4506baee46ff78d25263 P 21c967063a594d03b8a97db00e816f2e: No bootstrap required, opened a new log
I20260812 06:16:39.129386 21616 ts_tablet_manager.cc:1403] T 61bd6cce54da4506baee46ff78d25263 P 21c967063a594d03b8a97db00e816f2e: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:16:39.129914 21616 raft_consensus.cc:359] T 61bd6cce54da4506baee46ff78d25263 P 21c967063a594d03b8a97db00e816f2e [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "21c967063a594d03b8a97db00e816f2e" member_type: VOTER last_known_addr { host: "127.20.212.129" port: 33489 } }
I20260812 06:16:39.130092 21616 raft_consensus.cc:385] T 61bd6cce54da4506baee46ff78d25263 P 21c967063a594d03b8a97db00e816f2e [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:39.130138 21616 raft_consensus.cc:740] T 61bd6cce54da4506baee46ff78d25263 P 21c967063a594d03b8a97db00e816f2e [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 21c967063a594d03b8a97db00e816f2e, State: Initialized, Role: FOLLOWER
I20260812 06:16:39.130298 21616 consensus_queue.cc:260] T 61bd6cce54da4506baee46ff78d25263 P 21c967063a594d03b8a97db00e816f2e [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: "21c967063a594d03b8a97db00e816f2e" member_type: VOTER last_known_addr { host: "127.20.212.129" port: 33489 } }
I20260812 06:16:39.130429 21616 raft_consensus.cc:399] T 61bd6cce54da4506baee46ff78d25263 P 21c967063a594d03b8a97db00e816f2e [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:39.130476 21616 raft_consensus.cc:493] T 61bd6cce54da4506baee46ff78d25263 P 21c967063a594d03b8a97db00e816f2e [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:39.130527 21616 raft_consensus.cc:3060] T 61bd6cce54da4506baee46ff78d25263 P 21c967063a594d03b8a97db00e816f2e [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:39.131579 21616 raft_consensus.cc:515] T 61bd6cce54da4506baee46ff78d25263 P 21c967063a594d03b8a97db00e816f2e [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "21c967063a594d03b8a97db00e816f2e" member_type: VOTER last_known_addr { host: "127.20.212.129" port: 33489 } }
I20260812 06:16:39.131734 21616 leader_election.cc:304] T 61bd6cce54da4506baee46ff78d25263 P 21c967063a594d03b8a97db00e816f2e [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: 21c967063a594d03b8a97db00e816f2e; no voters: 
I20260812 06:16:39.131951 21616 leader_election.cc:290] T 61bd6cce54da4506baee46ff78d25263 P 21c967063a594d03b8a97db00e816f2e [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:39.132119 21618 raft_consensus.cc:2804] T 61bd6cce54da4506baee46ff78d25263 P 21c967063a594d03b8a97db00e816f2e [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:39.132320 21616 ts_tablet_manager.cc:1434] T 61bd6cce54da4506baee46ff78d25263 P 21c967063a594d03b8a97db00e816f2e: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:16:39.132356 21618 raft_consensus.cc:697] T 61bd6cce54da4506baee46ff78d25263 P 21c967063a594d03b8a97db00e816f2e [term 1 LEADER]: Becoming Leader. State: Replica: 21c967063a594d03b8a97db00e816f2e, State: Running, Role: LEADER
I20260812 06:16:39.132522 21618 consensus_queue.cc:237] T 61bd6cce54da4506baee46ff78d25263 P 21c967063a594d03b8a97db00e816f2e [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: "21c967063a594d03b8a97db00e816f2e" member_type: VOTER last_known_addr { host: "127.20.212.129" port: 33489 } }
I20260812 06:16:39.132814 21598 heartbeater.cc:499] Master 127.20.212.190:43697 was elected leader, sending a full tablet report...
I20260812 06:16:39.135314 21393 catalog_manager.cc:5719] T 61bd6cce54da4506baee46ff78d25263 P 21c967063a594d03b8a97db00e816f2e reported cstate change: term changed from 0 to 1, leader changed from <none> to 21c967063a594d03b8a97db00e816f2e (127.20.212.129). New cstate: current_term: 1 leader_uuid: "21c967063a594d03b8a97db00e816f2e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "21c967063a594d03b8a97db00e816f2e" member_type: VOTER last_known_addr { host: "127.20.212.129" port: 33489 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:39.210147 21330 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.066s	user 0.025s	sys 0.008s
I20260812 06:16:39.338593 21599 maintenance_manager.cc:419] P 21c967063a594d03b8a97db00e816f2e: Scheduling FlushMRSOp(61bd6cce54da4506baee46ff78d25263): perf score=15.086190
I20260812 06:16:39.492722 21504 maintenance_manager.cc:643] P 21c967063a594d03b8a97db00e816f2e: FlushMRSOp(61bd6cce54da4506baee46ff78d25263) complete. Timing: real 0.154s	user 0.129s	sys 0.020s Metrics: {"bytes_written":11897249,"cfile_init":1,"compiler_manager_pool.queue_time_us":54,"delete_count":0,"dirs.queue_time_us":77,"dirs.run_cpu_time_us":228,"dirs.run_wall_time_us":721,"drs_written":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4,"lbm_write_time_us":39306,"lbm_writes_lt_1ms":657,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1450}
I20260812 06:16:39.493796 21599 maintenance_manager.cc:419] P 21c967063a594d03b8a97db00e816f2e: Scheduling LogGCOp(61bd6cce54da4506baee46ff78d25263): free 20743880 bytes of WAL
I20260812 06:16:39.494098 21504 log_reader.cc:385] T 61bd6cce54da4506baee46ff78d25263: removed 2 log segments from log reader
I20260812 06:16:39.494177 21504 log.cc:1079] T 61bd6cce54da4506baee46ff78d25263 P 21c967063a594d03b8a97db00e816f2e: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/61bd6cce54da4506baee46ff78d25263/wal-000000001 (ops 1-6)
I20260812 06:16:39.494251 21504 log.cc:1079] T 61bd6cce54da4506baee46ff78d25263 P 21c967063a594d03b8a97db00e816f2e: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/61bd6cce54da4506baee46ff78d25263/wal-000000002 (ops 7-11)
I20260812 06:16:39.498451 21504 maintenance_manager.cc:643] P 21c967063a594d03b8a97db00e816f2e: LogGCOp(61bd6cce54da4506baee46ff78d25263) complete. Timing: real 0.004s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:16:39.498783 21599 maintenance_manager.cc:419] P 21c967063a594d03b8a97db00e816f2e: Scheduling UndoDeltaBlockGCOp(61bd6cce54da4506baee46ff78d25263): 12719217 bytes on disk
I20260812 06:16:39.499302 21504 maintenance_manager.cc:643] P 21c967063a594d03b8a97db00e816f2e: UndoDeltaBlockGCOp(61bd6cce54da4506baee46ff78d25263) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4}
I20260812 06:16:39.499683 21599 maintenance_manager.cc:419] P 21c967063a594d03b8a97db00e816f2e: Scheduling FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263): perf score=2.188937
I20260812 06:16:39.518736 21504 maintenance_manager.cc:643] P 21c967063a594d03b8a97db00e816f2e: FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263) complete. Timing: real 0.019s	user 0.016s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6821,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:39.519198 21599 maintenance_manager.cc:419] P 21c967063a594d03b8a97db00e816f2e: Scheduling MajorDeltaCompactionOp(61bd6cce54da4506baee46ff78d25263): perf score=1.000000
I20260812 06:16:39.652509 21504 maintenance_manager.cc:643] P 21c967063a594d03b8a97db00e816f2e: MajorDeltaCompactionOp(61bd6cce54da4506baee46ff78d25263) complete. Timing: real 0.133s	user 0.108s	sys 0.025s Metrics: {"cfile_cache_miss":422,"cfile_cache_miss_bytes":20262036,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":509,"lbm_read_time_us":8702,"lbm_reads_lt_1ms":450,"lbm_write_time_us":26062,"lbm_writes_lt_1ms":433,"mutex_wait_us":21,"peak_mem_usage":49238594,"reinsert_count":0,"spinlock_wait_cycles":7424,"thread_start_us":356,"threads_started":5,"update_count":1950}
I20260812 06:16:39.653105 21599 maintenance_manager.cc:419] P 21c967063a594d03b8a97db00e816f2e: Scheduling FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263): perf score=10.126437
I20260812 06:16:39.697878 21504 maintenance_manager.cc:643] P 21c967063a594d03b8a97db00e816f2e: FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263) complete. Timing: real 0.045s	user 0.026s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17659,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:16:39.698382 21599 maintenance_manager.cc:419] P 21c967063a594d03b8a97db00e816f2e: Scheduling FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263): perf score=2.188937
I20260812 06:16:39.709458 21504 maintenance_manager.cc:643] P 21c967063a594d03b8a97db00e816f2e: FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4080,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:39.710171 21599 maintenance_manager.cc:419] P 21c967063a594d03b8a97db00e816f2e: Scheduling MajorDeltaCompactionOp(61bd6cce54da4506baee46ff78d25263): perf score=1.000000
I20260812 06:16:39.846052 21504 maintenance_manager.cc:643] P 21c967063a594d03b8a97db00e816f2e: MajorDeltaCompactionOp(61bd6cce54da4506baee46ff78d25263) complete. Timing: real 0.136s	user 0.104s	sys 0.027s 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":275,"lbm_read_time_us":9805,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25062,"lbm_writes_lt_1ms":443,"mutex_wait_us":56,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:16:39.846717 21599 maintenance_manager.cc:419] P 21c967063a594d03b8a97db00e816f2e: Scheduling FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263): perf score=10.126437
I20260812 06:16:39.899760 21504 maintenance_manager.cc:643] P 21c967063a594d03b8a97db00e816f2e: FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263) complete. Timing: real 0.053s	user 0.015s	sys 0.023s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":18226,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:16:39.900305 21599 maintenance_manager.cc:419] P 21c967063a594d03b8a97db00e816f2e: Scheduling FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263): perf score=2.188937
I20260812 06:16:39.915473 21504 maintenance_manager.cc:643] P 21c967063a594d03b8a97db00e816f2e: FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5602,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:39.916117 21599 maintenance_manager.cc:419] P 21c967063a594d03b8a97db00e816f2e: Scheduling MajorDeltaCompactionOp(61bd6cce54da4506baee46ff78d25263): perf score=1.000000
I20260812 06:16:40.047181 21504 maintenance_manager.cc:643] P 21c967063a594d03b8a97db00e816f2e: MajorDeltaCompactionOp(61bd6cce54da4506baee46ff78d25263) complete. Timing: real 0.131s	user 0.101s	sys 0.029s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672275,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":311,"lbm_read_time_us":9290,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24555,"lbm_writes_lt_1ms":443,"mutex_wait_us":41,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9984,"update_count":2000}
I20260812 06:16:40.048422 21599 maintenance_manager.cc:419] P 21c967063a594d03b8a97db00e816f2e: Scheduling FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263): perf score=10.126437
I20260812 06:16:40.093900 21504 maintenance_manager.cc:643] P 21c967063a594d03b8a97db00e816f2e: FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263) complete. Timing: real 0.045s	user 0.016s	sys 0.027s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15504,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:40.094597 21599 maintenance_manager.cc:419] P 21c967063a594d03b8a97db00e816f2e: Scheduling FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263): perf score=2.188937
I20260812 06:16:40.106456 21504 maintenance_manager.cc:643] P 21c967063a594d03b8a97db00e816f2e: FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263) complete. Timing: real 0.012s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4290,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:40.107000 21599 maintenance_manager.cc:419] P 21c967063a594d03b8a97db00e816f2e: Scheduling MajorDeltaCompactionOp(61bd6cce54da4506baee46ff78d25263): perf score=1.000000
I20260812 06:16:40.262136 21504 maintenance_manager.cc:643] P 21c967063a594d03b8a97db00e816f2e: MajorDeltaCompactionOp(61bd6cce54da4506baee46ff78d25263) complete. Timing: real 0.155s	user 0.125s	sys 0.027s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1077,"lbm_read_time_us":12632,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26711,"lbm_writes_lt_1ms":443,"mutex_wait_us":310,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6528,"update_count":2000}
I20260812 06:16:40.262606 21599 maintenance_manager.cc:419] P 21c967063a594d03b8a97db00e816f2e: Scheduling FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263): perf score=10.126437
I20260812 06:16:40.314652 21504 maintenance_manager.cc:643] P 21c967063a594d03b8a97db00e816f2e: FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263) complete. Timing: real 0.052s	user 0.023s	sys 0.015s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":17707,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:40.315155 21599 maintenance_manager.cc:419] P 21c967063a594d03b8a97db00e816f2e: Scheduling FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263): perf score=2.188937
I20260812 06:16:40.326210 21504 maintenance_manager.cc:643] P 21c967063a594d03b8a97db00e816f2e: FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4245,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:40.326884 21599 maintenance_manager.cc:419] P 21c967063a594d03b8a97db00e816f2e: Scheduling MajorDeltaCompactionOp(61bd6cce54da4506baee46ff78d25263): perf score=1.000000
I20260812 06:16:40.445251 21504 maintenance_manager.cc:643] P 21c967063a594d03b8a97db00e816f2e: MajorDeltaCompactionOp(61bd6cce54da4506baee46ff78d25263) complete. Timing: real 0.118s	user 0.090s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":319,"lbm_read_time_us":8795,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22776,"lbm_writes_lt_1ms":443,"mutex_wait_us":114,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:16:40.445909 21599 maintenance_manager.cc:419] P 21c967063a594d03b8a97db00e816f2e: Scheduling FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263): perf score=10.126437
I20260812 06:16:40.481956 21504 maintenance_manager.cc:643] P 21c967063a594d03b8a97db00e816f2e: FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263) complete. Timing: real 0.036s	user 0.010s	sys 0.024s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15629,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:40.482496 21599 maintenance_manager.cc:419] P 21c967063a594d03b8a97db00e816f2e: Scheduling FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263): perf score=2.188937
I20260812 06:16:40.498046 21504 maintenance_manager.cc:643] P 21c967063a594d03b8a97db00e816f2e: FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5862,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:40.498643 21599 maintenance_manager.cc:419] P 21c967063a594d03b8a97db00e816f2e: Scheduling MajorDeltaCompactionOp(61bd6cce54da4506baee46ff78d25263): perf score=1.000000
I20260812 06:16:40.619110 21504 maintenance_manager.cc:643] P 21c967063a594d03b8a97db00e816f2e: MajorDeltaCompactionOp(61bd6cce54da4506baee46ff78d25263) complete. Timing: real 0.120s	user 0.104s	sys 0.016s 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":193,"lbm_read_time_us":9828,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21782,"lbm_writes_lt_1ms":443,"mutex_wait_us":51,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":23808,"update_count":2000}
I20260812 06:16:40.619843 21599 maintenance_manager.cc:419] P 21c967063a594d03b8a97db00e816f2e: Scheduling FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263): perf score=10.126437
I20260812 06:16:40.663587 21504 maintenance_manager.cc:643] P 21c967063a594d03b8a97db00e816f2e: FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263) complete. Timing: real 0.044s	user 0.028s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17080,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:40.664247 21599 maintenance_manager.cc:419] P 21c967063a594d03b8a97db00e816f2e: Scheduling FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263): perf score=2.188937
I20260812 06:16:40.683290 21504 maintenance_manager.cc:643] P 21c967063a594d03b8a97db00e816f2e: FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263) complete. Timing: real 0.019s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5593,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:40.683748 21599 maintenance_manager.cc:419] P 21c967063a594d03b8a97db00e816f2e: Scheduling FlushMRSOp(61bd6cce54da4506baee46ff78d25263): perf score=1.000000
I20260812 06:16:40.722766 21504 maintenance_manager.cc:643] P 21c967063a594d03b8a97db00e816f2e: FlushMRSOp(61bd6cce54da4506baee46ff78d25263) complete. Timing: real 0.039s	user 0.027s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":75,"dirs.run_cpu_time_us":235,"dirs.run_wall_time_us":1367,"drs_written":1,"lbm_read_time_us":103,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2075,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:16:40.723760 21599 maintenance_manager.cc:419] P 21c967063a594d03b8a97db00e816f2e: Scheduling UndoDeltaBlockGCOp(61bd6cce54da4506baee46ff78d25263): 447 bytes on disk
I20260812 06:16:40.724298 21504 maintenance_manager.cc:643] P 21c967063a594d03b8a97db00e816f2e: UndoDeltaBlockGCOp(61bd6cce54da4506baee46ff78d25263) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4}
I20260812 06:16:40.724768 21599 maintenance_manager.cc:419] P 21c967063a594d03b8a97db00e816f2e: Scheduling FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263): perf score=3.181125
I20260812 06:16:40.740356 21504 maintenance_manager.cc:643] P 21c967063a594d03b8a97db00e816f2e: FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263) complete. Timing: real 0.015s	user 0.012s	sys 0.003s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":6284,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:40.740828 21599 maintenance_manager.cc:419] P 21c967063a594d03b8a97db00e816f2e: Scheduling LogGCOp(61bd6cce54da4506baee46ff78d25263): free 108535453 bytes of WAL
I20260812 06:16:40.741062 21504 log_reader.cc:385] T 61bd6cce54da4506baee46ff78d25263: removed 11 log segments from log reader
I20260812 06:16:40.741108 21504 log.cc:1079] T 61bd6cce54da4506baee46ff78d25263 P 21c967063a594d03b8a97db00e816f2e: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/61bd6cce54da4506baee46ff78d25263/wal-000000003 (ops 12-16)
I20260812 06:16:40.741137 21504 log.cc:1079] T 61bd6cce54da4506baee46ff78d25263 P 21c967063a594d03b8a97db00e816f2e: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/61bd6cce54da4506baee46ff78d25263/wal-000000004 (ops 17-20)
I20260812 06:16:40.741197 21504 log.cc:1079] T 61bd6cce54da4506baee46ff78d25263 P 21c967063a594d03b8a97db00e816f2e: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/61bd6cce54da4506baee46ff78d25263/wal-000000005 (ops 21-25)
I20260812 06:16:40.741245 21504 log.cc:1079] T 61bd6cce54da4506baee46ff78d25263 P 21c967063a594d03b8a97db00e816f2e: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/61bd6cce54da4506baee46ff78d25263/wal-000000006 (ops 26-30)
I20260812 06:16:40.741303 21504 log.cc:1079] T 61bd6cce54da4506baee46ff78d25263 P 21c967063a594d03b8a97db00e816f2e: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/61bd6cce54da4506baee46ff78d25263/wal-000000007 (ops 31-35)
I20260812 06:16:40.741356 21504 log.cc:1079] T 61bd6cce54da4506baee46ff78d25263 P 21c967063a594d03b8a97db00e816f2e: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/61bd6cce54da4506baee46ff78d25263/wal-000000008 (ops 36-40)
I20260812 06:16:40.741394 21504 log.cc:1079] T 61bd6cce54da4506baee46ff78d25263 P 21c967063a594d03b8a97db00e816f2e: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/61bd6cce54da4506baee46ff78d25263/wal-000000009 (ops 41-44)
I20260812 06:16:40.741430 21504 log.cc:1079] T 61bd6cce54da4506baee46ff78d25263 P 21c967063a594d03b8a97db00e816f2e: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/61bd6cce54da4506baee46ff78d25263/wal-000000010 (ops 45-49)
I20260812 06:16:40.741468 21504 log.cc:1079] T 61bd6cce54da4506baee46ff78d25263 P 21c967063a594d03b8a97db00e816f2e: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/61bd6cce54da4506baee46ff78d25263/wal-000000011 (ops 50-54)
I20260812 06:16:40.741516 21504 log.cc:1079] T 61bd6cce54da4506baee46ff78d25263 P 21c967063a594d03b8a97db00e816f2e: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/61bd6cce54da4506baee46ff78d25263/wal-000000012 (ops 55-59)
I20260812 06:16:40.741554 21504 log.cc:1079] T 61bd6cce54da4506baee46ff78d25263 P 21c967063a594d03b8a97db00e816f2e: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/61bd6cce54da4506baee46ff78d25263/wal-000000013 (ops 60-64)
I20260812 06:16:40.765352 21504 maintenance_manager.cc:643] P 21c967063a594d03b8a97db00e816f2e: LogGCOp(61bd6cce54da4506baee46ff78d25263) complete. Timing: real 0.024s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:16:40.765815 21599 maintenance_manager.cc:419] P 21c967063a594d03b8a97db00e816f2e: Scheduling FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263): perf score=2.188937
I20260812 06:16:40.779733 21504 maintenance_manager.cc:643] P 21c967063a594d03b8a97db00e816f2e: FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263) complete. Timing: real 0.014s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3774459,"delete_count":0,"lbm_write_time_us":4348,"lbm_writes_lt_1ms":95,"reinsert_count":0,"update_count":460}
I20260812 06:16:40.780509 21599 maintenance_manager.cc:419] P 21c967063a594d03b8a97db00e816f2e: Scheduling LogGCOp(61bd6cce54da4506baee46ff78d25263): free 11564875 bytes of WAL
I20260812 06:16:40.780736 21504 log_reader.cc:385] T 61bd6cce54da4506baee46ff78d25263: removed 1 log segments from log reader
I20260812 06:16:40.780784 21504 log.cc:1079] T 61bd6cce54da4506baee46ff78d25263 P 21c967063a594d03b8a97db00e816f2e: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/61bd6cce54da4506baee46ff78d25263/wal-000000014 (ops 65-68)
I20260812 06:16:40.783108 21504 maintenance_manager.cc:643] P 21c967063a594d03b8a97db00e816f2e: LogGCOp(61bd6cce54da4506baee46ff78d25263) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:16:40.783430 21599 maintenance_manager.cc:419] P 21c967063a594d03b8a97db00e816f2e: Scheduling FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263): perf score=2.188937
I20260812 06:16:40.794965 21504 maintenance_manager.cc:643] P 21c967063a594d03b8a97db00e816f2e: FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4020608,"delete_count":0,"lbm_write_time_us":3897,"lbm_writes_lt_1ms":101,"reinsert_count":0,"update_count":490}
I20260812 06:16:40.795473 21599 maintenance_manager.cc:419] P 21c967063a594d03b8a97db00e816f2e: Scheduling MajorDeltaCompactionOp(61bd6cce54da4506baee46ff78d25263): perf score=1.000000
I20260812 06:16:40.987578 21504 maintenance_manager.cc:643] P 21c967063a594d03b8a97db00e816f2e: MajorDeltaCompactionOp(61bd6cce54da4506baee46ff78d25263) complete. Timing: real 0.192s	user 0.165s	sys 0.026s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979863,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":973,"lbm_read_time_us":14029,"lbm_reads_lt_1ms":775,"lbm_write_time_us":37318,"lbm_writes_lt_1ms":743,"mutex_wait_us":562,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":1152,"thread_start_us":88,"threads_started":1,"update_count":3500}
I20260812 06:16:40.988416 21599 maintenance_manager.cc:419] P 21c967063a594d03b8a97db00e816f2e: Scheduling FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263): perf score=14.095187
I20260812 06:16:41.044440 21504 maintenance_manager.cc:643] P 21c967063a594d03b8a97db00e816f2e: FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263) complete. Timing: real 0.056s	user 0.043s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25155,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:41.045081 21599 maintenance_manager.cc:419] P 21c967063a594d03b8a97db00e816f2e: Scheduling FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263): perf score=2.188937
I20260812 06:16:41.057706 21504 maintenance_manager.cc:643] P 21c967063a594d03b8a97db00e816f2e: FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263) complete. Timing: real 0.012s	user 0.002s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5025,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:41.058182 21599 maintenance_manager.cc:419] P 21c967063a594d03b8a97db00e816f2e: Scheduling MajorDeltaCompactionOp(61bd6cce54da4506baee46ff78d25263): perf score=1.000000
I20260812 06:16:41.204708 21504 maintenance_manager.cc:643] P 21c967063a594d03b8a97db00e816f2e: MajorDeltaCompactionOp(61bd6cce54da4506baee46ff78d25263) complete. Timing: real 0.146s	user 0.107s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":287,"lbm_read_time_us":9595,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29778,"lbm_writes_lt_1ms":543,"mutex_wait_us":53,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":64640,"update_count":2500}
I20260812 06:16:41.205852 21599 maintenance_manager.cc:419] P 21c967063a594d03b8a97db00e816f2e: Scheduling FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263): perf score=13.103000
I20260812 06:16:41.248914 21504 maintenance_manager.cc:643] P 21c967063a594d03b8a97db00e816f2e: FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263) complete. Timing: real 0.043s	user 0.033s	sys 0.008s Metrics: {"bytes_written":14563813,"delete_count":0,"lbm_write_time_us":18325,"lbm_writes_lt_1ms":358,"reinsert_count":0,"update_count":1775}
I20260812 06:16:41.249464 21599 maintenance_manager.cc:419] P 21c967063a594d03b8a97db00e816f2e: Scheduling FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263): perf score=1.000000
I20260812 06:16:41.260684 21504 maintenance_manager.cc:643] P 21c967063a594d03b8a97db00e816f2e: FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263) complete. Timing: real 0.011s	user 0.005s	sys 0.001s Metrics: {"bytes_written":2010382,"delete_count":0,"lbm_write_time_us":2445,"lbm_writes_lt_1ms":52,"reinsert_count":0,"update_count":245}
I20260812 06:16:41.261149 21599 maintenance_manager.cc:419] P 21c967063a594d03b8a97db00e816f2e: Scheduling MajorDeltaCompactionOp(61bd6cce54da4506baee46ff78d25263): perf score=1.000000
I20260812 06:16:41.416452 21504 maintenance_manager.cc:643] P 21c967063a594d03b8a97db00e816f2e: MajorDeltaCompactionOp(61bd6cce54da4506baee46ff78d25263) complete. Timing: real 0.155s	user 0.104s	sys 0.050s Metrics: {"cfile_cache_miss":436,"cfile_cache_miss_bytes":20836324,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":116,"lbm_read_time_us":10085,"lbm_reads_lt_1ms":468,"lbm_write_time_us":27001,"lbm_writes_lt_1ms":447,"mutex_wait_us":45,"peak_mem_usage":50853468,"reinsert_count":0,"spinlock_wait_cycles":6912,"update_count":2020}
I20260812 06:16:41.417287 21599 maintenance_manager.cc:419] P 21c967063a594d03b8a97db00e816f2e: Scheduling FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263): perf score=11.118625
I20260812 06:16:41.453253 21504 maintenance_manager.cc:643] P 21c967063a594d03b8a97db00e816f2e: FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263) complete. Timing: real 0.036s	user 0.031s	sys 0.004s Metrics: {"bytes_written":12553638,"delete_count":0,"lbm_write_time_us":15874,"lbm_writes_lt_1ms":309,"reinsert_count":0,"update_count":1530}
I20260812 06:16:41.454092 21599 maintenance_manager.cc:419] P 21c967063a594d03b8a97db00e816f2e: Scheduling FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263): perf score=2.188937
I20260812 06:16:41.471060 21504 maintenance_manager.cc:643] P 21c967063a594d03b8a97db00e816f2e: FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263) complete. Timing: real 0.017s	user 0.012s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6044,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:41.471570 21599 maintenance_manager.cc:419] P 21c967063a594d03b8a97db00e816f2e: Scheduling MajorDeltaCompactionOp(61bd6cce54da4506baee46ff78d25263): perf score=1.000000
I20260812 06:16:41.626621 21504 maintenance_manager.cc:643] P 21c967063a594d03b8a97db00e816f2e: MajorDeltaCompactionOp(61bd6cce54da4506baee46ff78d25263) complete. Timing: real 0.155s	user 0.117s	sys 0.011s Metrics: {"cfile_cache_miss":428,"cfile_cache_miss_bytes":20508171,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1363,"lbm_read_time_us":7665,"lbm_reads_lt_1ms":460,"lbm_write_time_us":25611,"lbm_writes_lt_1ms":439,"mutex_wait_us":576,"peak_mem_usage":49484804,"reinsert_count":0,"spinlock_wait_cycles":8320,"update_count":1980}
I20260812 06:16:41.627318 21599 maintenance_manager.cc:419] P 21c967063a594d03b8a97db00e816f2e: Scheduling FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263): perf score=14.095187
I20260812 06:16:41.721432 21504 maintenance_manager.cc:643] P 21c967063a594d03b8a97db00e816f2e: FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263) complete. Timing: real 0.094s	user 0.038s	sys 0.012s Metrics: {"bytes_written":15712491,"delete_count":0,"lbm_write_time_us":22856,"lbm_writes_lt_1ms":386,"reinsert_count":0,"update_count":1915}
I20260812 06:16:41.722039 21599 maintenance_manager.cc:419] P 21c967063a594d03b8a97db00e816f2e: Scheduling FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263): perf score=7.149875
I20260812 06:16:41.816731 21504 maintenance_manager.cc:643] P 21c967063a594d03b8a97db00e816f2e: FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263) complete. Timing: real 0.094s	user 0.023s	sys 0.008s Metrics: {"bytes_written":8902491,"delete_count":0,"lbm_write_time_us":13107,"lbm_writes_lt_1ms":220,"reinsert_count":0,"update_count":1085}
I20260812 06:16:41.817342 21599 maintenance_manager.cc:419] P 21c967063a594d03b8a97db00e816f2e: Scheduling FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263): perf score=6.157687
I20260812 06:16:41.918692 21504 maintenance_manager.cc:643] P 21c967063a594d03b8a97db00e816f2e: FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263) complete. Timing: real 0.101s	user 0.023s	sys 0.005s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":12169,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:41.919449 21599 maintenance_manager.cc:419] P 21c967063a594d03b8a97db00e816f2e: Scheduling FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263): perf score=6.157687
I20260812 06:16:42.019675 21504 maintenance_manager.cc:643] P 21c967063a594d03b8a97db00e816f2e: FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263) complete. Timing: real 0.100s	user 0.023s	sys 0.000s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":9616,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:42.020483 21599 maintenance_manager.cc:419] P 21c967063a594d03b8a97db00e816f2e: Scheduling FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263): perf score=7.149875
I20260812 06:16:42.114576 21504 maintenance_manager.cc:643] P 21c967063a594d03b8a97db00e816f2e: FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263) complete. Timing: real 0.094s	user 0.010s	sys 0.015s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":11487,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:16:42.115159 21599 maintenance_manager.cc:419] P 21c967063a594d03b8a97db00e816f2e: Scheduling FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263): perf score=8.142062
I20260812 06:16:42.213518 21504 maintenance_manager.cc:643] P 21c967063a594d03b8a97db00e816f2e: FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263) complete. Timing: real 0.098s	user 0.018s	sys 0.012s Metrics: {"bytes_written":10297307,"delete_count":0,"lbm_write_time_us":13019,"lbm_writes_lt_1ms":254,"reinsert_count":0,"update_count":1255}
I20260812 06:16:42.214483 21599 maintenance_manager.cc:419] P 21c967063a594d03b8a97db00e816f2e: Scheduling FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263): perf score=8.142062
I20260812 06:16:42.317749 21504 maintenance_manager.cc:643] P 21c967063a594d03b8a97db00e816f2e: FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263) complete. Timing: real 0.103s	user 0.011s	sys 0.015s Metrics: {"bytes_written":9805026,"delete_count":0,"lbm_write_time_us":10815,"lbm_writes_lt_1ms":242,"reinsert_count":0,"update_count":1195}
I20260812 06:16:42.318697 21599 maintenance_manager.cc:419] P 21c967063a594d03b8a97db00e816f2e: Scheduling FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263): perf score=9.134250
I20260812 06:16:42.417662 21504 maintenance_manager.cc:643] P 21c967063a594d03b8a97db00e816f2e: FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263) complete. Timing: real 0.099s	user 0.024s	sys 0.003s Metrics: {"bytes_written":11487012,"delete_count":0,"lbm_write_time_us":12393,"lbm_writes_lt_1ms":283,"reinsert_count":0,"update_count":1400}
I20260812 06:16:42.418216 21599 maintenance_manager.cc:419] P 21c967063a594d03b8a97db00e816f2e: Scheduling FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263): perf score=7.149875
I20260812 06:16:42.518489 21504 maintenance_manager.cc:643] P 21c967063a594d03b8a97db00e816f2e: FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263) complete. Timing: real 0.100s	user 0.016s	sys 0.008s Metrics: {"bytes_written":9025560,"delete_count":0,"lbm_write_time_us":10632,"lbm_writes_lt_1ms":223,"reinsert_count":0,"update_count":1100}
I20260812 06:16:42.519207 21599 maintenance_manager.cc:419] P 21c967063a594d03b8a97db00e816f2e: Scheduling FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263): perf score=7.149875
I20260812 06:16:42.619980 21504 maintenance_manager.cc:643] P 21c967063a594d03b8a97db00e816f2e: FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263) complete. Timing: real 0.101s	user 0.017s	sys 0.012s Metrics: {"bytes_written":8533271,"delete_count":0,"lbm_write_time_us":12852,"lbm_writes_lt_1ms":211,"reinsert_count":0,"update_count":1040}
I20260812 06:16:42.620832 21599 maintenance_manager.cc:419] P 21c967063a594d03b8a97db00e816f2e: Scheduling FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263): perf score=6.157687
I20260812 06:16:42.719224 21504 maintenance_manager.cc:643] P 21c967063a594d03b8a97db00e816f2e: FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263) complete. Timing: real 0.098s	user 0.007s	sys 0.012s Metrics: {"bytes_written":8328155,"delete_count":0,"lbm_write_time_us":8722,"lbm_writes_lt_1ms":206,"reinsert_count":0,"update_count":1015}
I20260812 06:16:42.719965 21599 maintenance_manager.cc:419] P 21c967063a594d03b8a97db00e816f2e: Scheduling FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263): perf score=10.126437
I20260812 06:16:42.819382 21504 maintenance_manager.cc:643] P 21c967063a594d03b8a97db00e816f2e: FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263) complete. Timing: real 0.099s	user 0.020s	sys 0.014s Metrics: {"bytes_written":11856222,"delete_count":0,"lbm_write_time_us":15497,"lbm_writes_lt_1ms":292,"reinsert_count":0,"update_count":1445}
I20260812 06:16:42.820300 21599 maintenance_manager.cc:419] P 21c967063a594d03b8a97db00e816f2e: Scheduling FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263): perf score=6.157687
I20260812 06:16:42.920476 21504 maintenance_manager.cc:643] P 21c967063a594d03b8a97db00e816f2e: FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263) complete. Timing: real 0.100s	user 0.012s	sys 0.013s Metrics: {"bytes_written":8205077,"delete_count":0,"lbm_write_time_us":10190,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:42.921273 21599 maintenance_manager.cc:419] P 21c967063a594d03b8a97db00e816f2e: Scheduling FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263): perf score=7.149875
I20260812 06:16:43.013569 21504 maintenance_manager.cc:643] P 21c967063a594d03b8a97db00e816f2e: FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263) complete. Timing: real 0.092s	user 0.018s	sys 0.008s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":11937,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:16:43.014360 21599 maintenance_manager.cc:419] P 21c967063a594d03b8a97db00e816f2e: Scheduling FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263): perf score=6.157687
I20260812 06:16:43.114082 21504 maintenance_manager.cc:643] P 21c967063a594d03b8a97db00e816f2e: FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263) complete. Timing: real 0.099s	user 0.005s	sys 0.016s Metrics: {"bytes_written":8164054,"delete_count":0,"lbm_write_time_us":9002,"lbm_writes_lt_1ms":202,"reinsert_count":0,"update_count":995}
I20260812 06:16:43.114944 21599 maintenance_manager.cc:419] P 21c967063a594d03b8a97db00e816f2e: Scheduling FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263): perf score=10.126437
I20260812 06:16:43.215462 21504 maintenance_manager.cc:643] P 21c967063a594d03b8a97db00e816f2e: FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263) complete. Timing: real 0.100s	user 0.021s	sys 0.012s Metrics: {"bytes_written":11938277,"delete_count":0,"lbm_write_time_us":15375,"lbm_writes_lt_1ms":294,"reinsert_count":0,"update_count":1455}
I20260812 06:16:43.216346 21599 maintenance_manager.cc:419] P 21c967063a594d03b8a97db00e816f2e: Scheduling FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263): perf score=6.157687
I20260812 06:16:43.312484 21504 maintenance_manager.cc:643] P 21c967063a594d03b8a97db00e816f2e: FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263) complete. Timing: real 0.096s	user 0.013s	sys 0.013s Metrics: {"bytes_written":8205077,"delete_count":0,"lbm_write_time_us":10990,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:43.313197 21599 maintenance_manager.cc:419] P 21c967063a594d03b8a97db00e816f2e: Scheduling FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263): perf score=6.157687
I20260812 06:16:43.415311 21504 maintenance_manager.cc:643] P 21c967063a594d03b8a97db00e816f2e: FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263) complete. Timing: real 0.102s	user 0.012s	sys 0.016s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":12790,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:43.415923 21599 maintenance_manager.cc:419] P 21c967063a594d03b8a97db00e816f2e: Scheduling FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263): perf score=7.149875
I20260812 06:16:43.512410 21504 maintenance_manager.cc:643] P 21c967063a594d03b8a97db00e816f2e: FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263) complete. Timing: real 0.096s	user 0.012s	sys 0.013s Metrics: {"bytes_written":8615324,"delete_count":0,"lbm_write_time_us":10416,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:16:43.513253 21599 maintenance_manager.cc:419] P 21c967063a594d03b8a97db00e816f2e: Scheduling FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263): perf score=7.149875
I20260812 06:16:43.615935 21504 maintenance_manager.cc:643] P 21c967063a594d03b8a97db00e816f2e: FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263) complete. Timing: real 0.102s	user 0.013s	sys 0.008s Metrics: {"bytes_written":9435800,"delete_count":0,"lbm_write_time_us":9956,"lbm_writes_lt_1ms":233,"reinsert_count":0,"update_count":1150}
I20260812 06:16:43.617079 21599 maintenance_manager.cc:419] P 21c967063a594d03b8a97db00e816f2e: Scheduling FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263): perf score=9.134250
I20260812 06:16:43.717374 21504 maintenance_manager.cc:643] P 21c967063a594d03b8a97db00e816f2e: FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263) complete. Timing: real 0.100s	user 0.014s	sys 0.017s Metrics: {"bytes_written":10666535,"delete_count":0,"lbm_write_time_us":13101,"lbm_writes_lt_1ms":263,"reinsert_count":0,"update_count":1300}
I20260812 06:16:43.718019 21599 maintenance_manager.cc:419] P 21c967063a594d03b8a97db00e816f2e: Scheduling FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263): perf score=7.149875
I20260812 06:16:43.786590 21330 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.576s	user 1.723s	sys 0.091s
I20260812 06:16:43.812670 21504 maintenance_manager.cc:643] P 21c967063a594d03b8a97db00e816f2e: FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263) complete. Timing: real 0.094s	user 0.008s	sys 0.012s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":9172,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:16:43.813344 21599 maintenance_manager.cc:419] P 21c967063a594d03b8a97db00e816f2e: Scheduling FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263): perf score=6.157687
I20260812 06:16:43.911084 21504 maintenance_manager.cc:643] P 21c967063a594d03b8a97db00e816f2e: FlushDeltaMemStoresOp(61bd6cce54da4506baee46ff78d25263) complete. Timing: real 0.098s	user 0.009s	sys 0.008s Metrics: {"bytes_written":7794836,"delete_count":0,"lbm_write_time_us":8077,"lbm_writes_lt_1ms":193,"reinsert_count":0,"update_count":950}
I20260812 06:16:43.911743 21599 maintenance_manager.cc:419] P 21c967063a594d03b8a97db00e816f2e: Scheduling FlushMRSOp(61bd6cce54da4506baee46ff78d25263): perf score=1.195565
I20260812 06:16:44.010962 21504 maintenance_manager.cc:643] P 21c967063a594d03b8a97db00e816f2e: FlushMRSOp(61bd6cce54da4506baee46ff78d25263) complete. Timing: real 0.099s	user 0.024s	sys 0.008s Metrics: {"bytes_written":2791865,"cfile_init":1,"dirs.queue_time_us":218,"drs_written":1,"lbm_read_time_us":34,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2998,"lbm_writes_lt_1ms":49,"peak_mem_usage":0,"rows_written":68,"spinlock_wait_cycles":768,"thread_start_us":117,"threads_started":1}
I20260812 06:16:44.011730 21599 maintenance_manager.cc:419] P 21c967063a594d03b8a97db00e816f2e: Scheduling LogGCOp(61bd6cce54da4506baee46ff78d25263): free 254031132 bytes of WAL
I20260812 06:16:44.012118 21504 log_reader.cc:385] T 61bd6cce54da4506baee46ff78d25263: removed 25 log segments from log reader
I20260812 06:16:44.012193 21504 log.cc:1079] T 61bd6cce54da4506baee46ff78d25263 P 21c967063a594d03b8a97db00e816f2e: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/61bd6cce54da4506baee46ff78d25263/wal-000000015 (ops 69-73)
I20260812 06:16:44.012279 21504 log.cc:1079] T 61bd6cce54da4506baee46ff78d25263 P 21c967063a594d03b8a97db00e816f2e: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/61bd6cce54da4506baee46ff78d25263/wal-000000016 (ops 74-78)
I20260812 06:16:44.012343 21504 log.cc:1079] T 61bd6cce54da4506baee46ff78d25263 P 21c967063a594d03b8a97db00e816f2e: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/61bd6cce54da4506baee46ff78d25263/wal-000000017 (ops 79-82)
I20260812 06:16:44.012419 21504 log.cc:1079] T 61bd6cce54da4506baee46ff78d25263 P 21c967063a594d03b8a97db00e816f2e: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/61bd6cce54da4506baee46ff78d25263/wal-000000018 (ops 83-87)
I20260812 06:16:44.012460 21504 log.cc:1079] T 61bd6cce54da4506baee46ff78d25263 P 21c967063a594d03b8a97db00e816f2e: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/61bd6cce54da4506baee46ff78d25263/wal-000000019 (ops 88-92)
I20260812 06:16:44.012526 21504 log.cc:1079] T 61bd6cce54da4506baee46ff78d25263 P 21c967063a594d03b8a97db00e816f2e: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/61bd6cce54da4506baee46ff78d25263/wal-000000020 (ops 93-97)
I20260812 06:16:44.012565 21504 log.cc:1079] T 61bd6cce54da4506baee46ff78d25263 P 21c967063a594d03b8a97db00e816f2e: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/61bd6cce54da4506baee46ff78d25263/wal-000000021 (ops 98-102)
I20260812 06:16:44.012612 21504 log.cc:1079] T 61bd6cce54da4506baee46ff78d25263 P 21c967063a594d03b8a97db00e816f2e: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/61bd6cce54da4506baee46ff78d25263/wal-000000022 (ops 103-107)
I20260812 06:16:44.012655 21504 log.cc:1079] T 61bd6cce54da4506baee46ff78d25263 P 21c967063a594d03b8a97db00e816f2e: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/61bd6cce54da4506baee46ff78d25263/wal-000000023 (ops 108-112)
I20260812 06:16:44.012701 21504 log.cc:1079] T 61bd6cce54da4506baee46ff78d25263 P 21c967063a594d03b8a97db00e816f2e: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/61bd6cce54da4506baee46ff78d25263/wal-000000024 (ops 113-117)
I20260812 06:16:44.012748 21504 log.cc:1079] T 61bd6cce54da4506baee46ff78d25263 P 21c967063a594d03b8a97db00e816f2e: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/61bd6cce54da4506baee46ff78d25263/wal-000000025 (ops 118-122)
I20260812 06:16:44.012792 21504 log.cc:1079] T 61bd6cce54da4506baee46ff78d25263 P 21c967063a594d03b8a97db00e816f2e: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/61bd6cce54da4506baee46ff78d25263/wal-000000026 (ops 123-127)
I20260812 06:16:44.012840 21504 log.cc:1079] T 61bd6cce54da4506baee46ff78d25263 P 21c967063a594d03b8a97db00e816f2e: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/61bd6cce54da4506baee46ff78d25263/wal-000000027 (ops 128-132)
I20260812 06:16:44.012883 21504 log.cc:1079] T 61bd6cce54da4506baee46ff78d25263 P 21c967063a594d03b8a97db00e816f2e: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/61bd6cce54da4506baee46ff78d25263/wal-000000028 (ops 133-137)
I20260812 06:16:44.012928 21504 log.cc:1079] T 61bd6cce54da4506baee46ff78d25263 P 21c967063a594d03b8a97db00e816f2e: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/61bd6cce54da4506baee46ff78d25263/wal-000000029 (ops 138-142)
I20260812 06:16:44.013015 21504 log.cc:1079] T 61bd6cce54da4506baee46ff78d25263 P 21c967063a594d03b8a97db00e816f2e: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/61bd6cce54da4506baee46ff78d25263/wal-000000030 (ops 143-147)
I20260812 06:16:44.013055 21504 log.cc:1079] T 61bd6cce54da4506baee46ff78d25263 P 21c967063a594d03b8a97db00e816f2e: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/61bd6cce54da4506baee46ff78d25263/wal-000000031 (ops 148-152)
I20260812 06:16:44.013126 21504 log.cc:1079] T 61bd6cce54da4506baee46ff78d25263 P 21c967063a594d03b8a97db00e816f2e: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/61bd6cce54da4506baee46ff78d25263/wal-000000032 (ops 153-156)
I20260812 06:16:44.013166 21504 log.cc:1079] T 61bd6cce54da4506baee46ff78d25263 P 21c967063a594d03b8a97db00e816f2e: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/61bd6cce54da4506baee46ff78d25263/wal-000000033 (ops 157-161)
I20260812 06:16:44.013240 21504 log.cc:1079] T 61bd6cce54da4506baee46ff78d25263 P 21c967063a594d03b8a97db00e816f2e: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/61bd6cce54da4506baee46ff78d25263/wal-000000034 (ops 162-166)
I20260812 06:16:44.013280 21504 log.cc:1079] T 61bd6cce54da4506baee46ff78d25263 P 21c967063a594d03b8a97db00e816f2e: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/61bd6cce54da4506baee46ff78d25263/wal-000000035 (ops 167-171)
I20260812 06:16:44.013348 21504 log.cc:1079] T 61bd6cce54da4506baee46ff78d25263 P 21c967063a594d03b8a97db00e816f2e: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/61bd6cce54da4506baee46ff78d25263/wal-000000036 (ops 172-176)
I20260812 06:16:44.013387 21504 log.cc:1079] T 61bd6cce54da4506baee46ff78d25263 P 21c967063a594d03b8a97db00e816f2e: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/61bd6cce54da4506baee46ff78d25263/wal-000000037 (ops 177-181)
I20260812 06:16:44.013458 21504 log.cc:1079] T 61bd6cce54da4506baee46ff78d25263 P 21c967063a594d03b8a97db00e816f2e: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/61bd6cce54da4506baee46ff78d25263/wal-000000038 (ops 182-186)
I20260812 06:16:44.013499 21504 log.cc:1079] T 61bd6cce54da4506baee46ff78d25263 P 21c967063a594d03b8a97db00e816f2e: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/61bd6cce54da4506baee46ff78d25263/wal-000000039 (ops 187-191)
I20260812 06:16:44.063874 21504 maintenance_manager.cc:643] P 21c967063a594d03b8a97db00e816f2e: LogGCOp(61bd6cce54da4506baee46ff78d25263) complete. Timing: real 0.052s	user 0.001s	sys 0.047s Metrics: {"spinlock_wait_cycles":1920}
I20260812 06:16:44.064412 21599 maintenance_manager.cc:419] P 21c967063a594d03b8a97db00e816f2e: Scheduling MajorDeltaCompactionOp(61bd6cce54da4506baee46ff78d25263): perf score=1.000000
W20260812 06:16:44.351217 21330 scanner-internal.cc:458] Time spent opening tablet: real 0.564s	user 0.002s	sys 0.000s
I20260812 06:16:44.353410 21330 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.566s	user 0.003s	sys 0.000s
I20260812 06:16:44.354012 21330 tablet_server.cc:179] TabletServer@127.20.212.129:0 shutting down...
I20260812 06:16:45.175186 21504 maintenance_manager.cc:643] P 21c967063a594d03b8a97db00e816f2e: MajorDeltaCompactionOp(61bd6cce54da4506baee46ff78d25263) complete. Timing: real 1.111s	user 0.616s	sys 0.491s Metrics: {"cfile_cache_hit":3981,"cfile_cache_hit_bytes":162470405,"cfile_cache_miss":1372,"cfile_cache_miss_bytes":59222621,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":23,"delta_iterators_relevant":23,"dirs.queue_time_us":1477,"lbm_read_time_us":24324,"lbm_reads_lt_1ms":1408,"lbm_write_time_us":233384,"lbm_writes_lt_1ms":5347,"peak_mem_usage":659591356,"reinsert_count":0,"spinlock_wait_cycles":1748736,"thread_start_us":597,"threads_started":7,"update_count":26500,"wal-append.queue_time_us":236}
I20260812 06:16:45.175962 21330 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:16:45.176417 21330 tablet_replica.cc:333] T 61bd6cce54da4506baee46ff78d25263 P 21c967063a594d03b8a97db00e816f2e: stopping tablet replica
I20260812 06:16:45.176687 21330 raft_consensus.cc:2243] T 61bd6cce54da4506baee46ff78d25263 P 21c967063a594d03b8a97db00e816f2e [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:45.176957 21330 raft_consensus.cc:2272] T 61bd6cce54da4506baee46ff78d25263 P 21c967063a594d03b8a97db00e816f2e [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:45.192471 21330 tablet_server.cc:196] TabletServer@127.20.212.129:0 shutdown complete.
I20260812 06:16:46.012265 21330 master.cc:562] Master@127.20.212.190:43697 shutting down...
I20260812 06:16:46.016146 21330 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 0dac71499d65473891d61d933fe12b11 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:46.016362 21330 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 0dac71499d65473891d61d933fe12b11 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:46.016456 21330 tablet_replica.cc:333] T 00000000000000000000000000000000 P 0dac71499d65473891d61d933fe12b11: stopping tablet replica
I20260812 06:16:46.028975 21330 master.cc:584] Master@127.20.212.190:43697 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (7158 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:16:46.146431 21330 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.20.212.190:33991
I20260812 06:16:46.146911 21330 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:46.149539 21665 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:46.149552 21330 server_base.cc:1061] running on GCE node
W20260812 06:16:46.149675 21659 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:46.149564 21661 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:46.149986 21330 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:46.150035 21330 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:46.150051 21330 hybrid_clock.cc:648] HybridClock initialized: now 1786515406150051 us; error 0 us; skew 500 ppm
I20260812 06:16:46.150935 21330 webserver.cc:533] Webserver started at http://127.20.212.190:39265/ using document root <none> and password file <none>
I20260812 06:16:46.151124 21330 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:46.151175 21330 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:46.151281 21330 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:46.151726 21330 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398952044-21330-0/minicluster-data/master-0-root/instance:
uuid: "fbe54774b5c14908bdd7d6c85b5cfeba"
format_stamp: "Formatted at 2026-08-12 06:16:46 on dist-test-slave-t3q3"
I20260812 06:16:46.153370 21330 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:16:46.154315 21673 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:46.154574 21330 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:46.154680 21330 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398952044-21330-0/minicluster-data/master-0-root
uuid: "fbe54774b5c14908bdd7d6c85b5cfeba"
format_stamp: "Formatted at 2026-08-12 06:16:46 on dist-test-slave-t3q3"
I20260812 06:16:46.154770 21330 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398952044-21330-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398952044-21330-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398952044-21330-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:46.166647 21330 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:46.167074 21330 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:46.171511 21330 rpc_server.cc:307] RPC server started. Bound to: 127.20.212.190:33991
I20260812 06:16:46.173425 21762 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.20.212.190:33991 every 8 connection(s)
I20260812 06:16:46.175310 21763 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:46.196393 21763 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P fbe54774b5c14908bdd7d6c85b5cfeba: Bootstrap starting.
I20260812 06:16:46.197299 21763 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P fbe54774b5c14908bdd7d6c85b5cfeba: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:46.198475 21763 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P fbe54774b5c14908bdd7d6c85b5cfeba: No bootstrap required, opened a new log
I20260812 06:16:46.198895 21763 raft_consensus.cc:359] T 00000000000000000000000000000000 P fbe54774b5c14908bdd7d6c85b5cfeba [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "fbe54774b5c14908bdd7d6c85b5cfeba" member_type: VOTER }
I20260812 06:16:46.199008 21763 raft_consensus.cc:385] T 00000000000000000000000000000000 P fbe54774b5c14908bdd7d6c85b5cfeba [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:46.199095 21763 raft_consensus.cc:740] T 00000000000000000000000000000000 P fbe54774b5c14908bdd7d6c85b5cfeba [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: fbe54774b5c14908bdd7d6c85b5cfeba, State: Initialized, Role: FOLLOWER
I20260812 06:16:46.199262 21763 consensus_queue.cc:260] T 00000000000000000000000000000000 P fbe54774b5c14908bdd7d6c85b5cfeba [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: "fbe54774b5c14908bdd7d6c85b5cfeba" member_type: VOTER }
I20260812 06:16:46.199361 21763 raft_consensus.cc:399] T 00000000000000000000000000000000 P fbe54774b5c14908bdd7d6c85b5cfeba [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:46.199410 21763 raft_consensus.cc:493] T 00000000000000000000000000000000 P fbe54774b5c14908bdd7d6c85b5cfeba [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:46.199469 21763 raft_consensus.cc:3060] T 00000000000000000000000000000000 P fbe54774b5c14908bdd7d6c85b5cfeba [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:46.200169 21763 raft_consensus.cc:515] T 00000000000000000000000000000000 P fbe54774b5c14908bdd7d6c85b5cfeba [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "fbe54774b5c14908bdd7d6c85b5cfeba" member_type: VOTER }
I20260812 06:16:46.200335 21763 leader_election.cc:304] T 00000000000000000000000000000000 P fbe54774b5c14908bdd7d6c85b5cfeba [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: fbe54774b5c14908bdd7d6c85b5cfeba; no voters: 
I20260812 06:16:46.200546 21763 leader_election.cc:290] T 00000000000000000000000000000000 P fbe54774b5c14908bdd7d6c85b5cfeba [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:46.200695 21767 raft_consensus.cc:2804] T 00000000000000000000000000000000 P fbe54774b5c14908bdd7d6c85b5cfeba [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:46.200950 21767 raft_consensus.cc:697] T 00000000000000000000000000000000 P fbe54774b5c14908bdd7d6c85b5cfeba [term 1 LEADER]: Becoming Leader. State: Replica: fbe54774b5c14908bdd7d6c85b5cfeba, State: Running, Role: LEADER
I20260812 06:16:46.201059 21763 sys_catalog.cc:565] T 00000000000000000000000000000000 P fbe54774b5c14908bdd7d6c85b5cfeba [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:46.201097 21767 consensus_queue.cc:237] T 00000000000000000000000000000000 P fbe54774b5c14908bdd7d6c85b5cfeba [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: "fbe54774b5c14908bdd7d6c85b5cfeba" member_type: VOTER }
I20260812 06:16:46.201532 21768 sys_catalog.cc:455] T 00000000000000000000000000000000 P fbe54774b5c14908bdd7d6c85b5cfeba [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "fbe54774b5c14908bdd7d6c85b5cfeba" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "fbe54774b5c14908bdd7d6c85b5cfeba" member_type: VOTER } }
I20260812 06:16:46.201634 21768 sys_catalog.cc:458] T 00000000000000000000000000000000 P fbe54774b5c14908bdd7d6c85b5cfeba [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:46.201749 21769 sys_catalog.cc:455] T 00000000000000000000000000000000 P fbe54774b5c14908bdd7d6c85b5cfeba [sys.catalog]: SysCatalogTable state changed. Reason: New leader fbe54774b5c14908bdd7d6c85b5cfeba. Latest consensus state: current_term: 1 leader_uuid: "fbe54774b5c14908bdd7d6c85b5cfeba" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "fbe54774b5c14908bdd7d6c85b5cfeba" member_type: VOTER } }
I20260812 06:16:46.201889 21769 sys_catalog.cc:458] T 00000000000000000000000000000000 P fbe54774b5c14908bdd7d6c85b5cfeba [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:46.202232 21774 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:46.203104 21774 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:46.203297 21330 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:46.205031 21774 catalog_manager.cc:1383] Generated new cluster ID: cb6be6fe882f4390b08a0948f93974c2
I20260812 06:16:46.205093 21774 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:46.218307 21774 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:46.218828 21774 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:46.228219 21774 catalog_manager.cc:6092] T 00000000000000000000000000000000 P fbe54774b5c14908bdd7d6c85b5cfeba: Generated new TSK 0
I20260812 06:16:46.228379 21774 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:46.235766 21330 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:46.237722 21796 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:46.237789 21800 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:46.237789 21797 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:46.238052 21330 server_base.cc:1061] running on GCE node
I20260812 06:16:46.238272 21330 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:46.238312 21330 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:46.238328 21330 hybrid_clock.cc:648] HybridClock initialized: now 1786515406238328 us; error 0 us; skew 500 ppm
I20260812 06:16:46.239212 21330 webserver.cc:533] Webserver started at http://127.20.212.129:44339/ using document root <none> and password file <none>
I20260812 06:16:46.239390 21330 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:46.239468 21330 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:46.239583 21330 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:46.239974 21330 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398952044-21330-0/minicluster-data/ts-0-root/instance:
uuid: "fa3c25ddb9714878b0c81f388fc9e542"
format_stamp: "Formatted at 2026-08-12 06:16:46 on dist-test-slave-t3q3"
I20260812 06:16:46.241480 21330 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:16:46.242462 21806 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:46.242733 21330 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:16:46.242825 21330 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398952044-21330-0/minicluster-data/ts-0-root
uuid: "fa3c25ddb9714878b0c81f388fc9e542"
format_stamp: "Formatted at 2026-08-12 06:16:46 on dist-test-slave-t3q3"
I20260812 06:16:46.242913 21330 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398952044-21330-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398952044-21330-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398952044-21330-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:46.273293 21330 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:46.273717 21330 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:46.274065 21330 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:46.274564 21330 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:46.274624 21330 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:46.274683 21330 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:46.274734 21330 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:46.278781 21330 rpc_server.cc:307] RPC server started. Bound to: 127.20.212.129:41645
I20260812 06:16:46.278860 21910 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.20.212.129:41645 every 8 connection(s)
I20260812 06:16:46.287269 21912 heartbeater.cc:344] Connected to a master server at 127.20.212.190:33991
I20260812 06:16:46.287393 21912 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:46.287639 21912 heartbeater.cc:507] Master 127.20.212.190:33991 requested a full tablet report, sending...
I20260812 06:16:46.288321 21704 ts_manager.cc:194] Registered new tserver with Master: fa3c25ddb9714878b0c81f388fc9e542 (127.20.212.129:41645)
I20260812 06:16:46.289047 21704 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:33988
I20260812 06:16:46.289217 21330 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.009981723s
I20260812 06:16:46.296139 21704 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:34004:
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:46.304806 21854 tablet_service.cc:1511] Processing CreateTablet for tablet 32cd746a463144e19cdc78282ebfb81a (DEFAULT_TABLE table=heavy-update-compaction-test [id=7fb89289b2d0413d87a2c7dcfee8b70a]), partition=
I20260812 06:16:46.305104 21854 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 32cd746a463144e19cdc78282ebfb81a. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:46.307149 21930 tablet_bootstrap.cc:492] T 32cd746a463144e19cdc78282ebfb81a P fa3c25ddb9714878b0c81f388fc9e542: Bootstrap starting.
I20260812 06:16:46.308044 21930 tablet_bootstrap.cc:654] T 32cd746a463144e19cdc78282ebfb81a P fa3c25ddb9714878b0c81f388fc9e542: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:46.309083 21930 tablet_bootstrap.cc:492] T 32cd746a463144e19cdc78282ebfb81a P fa3c25ddb9714878b0c81f388fc9e542: No bootstrap required, opened a new log
I20260812 06:16:46.309197 21930 ts_tablet_manager.cc:1403] T 32cd746a463144e19cdc78282ebfb81a P fa3c25ddb9714878b0c81f388fc9e542: Time spent bootstrapping tablet: real 0.002s	user 0.000s	sys 0.001s
I20260812 06:16:46.309617 21930 raft_consensus.cc:359] T 32cd746a463144e19cdc78282ebfb81a P fa3c25ddb9714878b0c81f388fc9e542 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "fa3c25ddb9714878b0c81f388fc9e542" member_type: VOTER last_known_addr { host: "127.20.212.129" port: 41645 } }
I20260812 06:16:46.309726 21930 raft_consensus.cc:385] T 32cd746a463144e19cdc78282ebfb81a P fa3c25ddb9714878b0c81f388fc9e542 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:46.309787 21930 raft_consensus.cc:740] T 32cd746a463144e19cdc78282ebfb81a P fa3c25ddb9714878b0c81f388fc9e542 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: fa3c25ddb9714878b0c81f388fc9e542, State: Initialized, Role: FOLLOWER
I20260812 06:16:46.309962 21930 consensus_queue.cc:260] T 32cd746a463144e19cdc78282ebfb81a P fa3c25ddb9714878b0c81f388fc9e542 [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: "fa3c25ddb9714878b0c81f388fc9e542" member_type: VOTER last_known_addr { host: "127.20.212.129" port: 41645 } }
I20260812 06:16:46.310077 21930 raft_consensus.cc:399] T 32cd746a463144e19cdc78282ebfb81a P fa3c25ddb9714878b0c81f388fc9e542 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:46.310127 21930 raft_consensus.cc:493] T 32cd746a463144e19cdc78282ebfb81a P fa3c25ddb9714878b0c81f388fc9e542 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:46.310180 21930 raft_consensus.cc:3060] T 32cd746a463144e19cdc78282ebfb81a P fa3c25ddb9714878b0c81f388fc9e542 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:46.311106 21930 raft_consensus.cc:515] T 32cd746a463144e19cdc78282ebfb81a P fa3c25ddb9714878b0c81f388fc9e542 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "fa3c25ddb9714878b0c81f388fc9e542" member_type: VOTER last_known_addr { host: "127.20.212.129" port: 41645 } }
I20260812 06:16:46.311257 21930 leader_election.cc:304] T 32cd746a463144e19cdc78282ebfb81a P fa3c25ddb9714878b0c81f388fc9e542 [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: fa3c25ddb9714878b0c81f388fc9e542; no voters: 
I20260812 06:16:46.311465 21930 leader_election.cc:290] T 32cd746a463144e19cdc78282ebfb81a P fa3c25ddb9714878b0c81f388fc9e542 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:46.311590 21934 raft_consensus.cc:2804] T 32cd746a463144e19cdc78282ebfb81a P fa3c25ddb9714878b0c81f388fc9e542 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:46.311811 21930 ts_tablet_manager.cc:1434] T 32cd746a463144e19cdc78282ebfb81a P fa3c25ddb9714878b0c81f388fc9e542: Time spent starting tablet: real 0.003s	user 0.000s	sys 0.003s
I20260812 06:16:46.311875 21934 raft_consensus.cc:697] T 32cd746a463144e19cdc78282ebfb81a P fa3c25ddb9714878b0c81f388fc9e542 [term 1 LEADER]: Becoming Leader. State: Replica: fa3c25ddb9714878b0c81f388fc9e542, State: Running, Role: LEADER
I20260812 06:16:46.312040 21912 heartbeater.cc:499] Master 127.20.212.190:33991 was elected leader, sending a full tablet report...
I20260812 06:16:46.312041 21934 consensus_queue.cc:237] T 32cd746a463144e19cdc78282ebfb81a P fa3c25ddb9714878b0c81f388fc9e542 [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: "fa3c25ddb9714878b0c81f388fc9e542" member_type: VOTER last_known_addr { host: "127.20.212.129" port: 41645 } }
I20260812 06:16:46.313546 21704 catalog_manager.cc:5719] T 32cd746a463144e19cdc78282ebfb81a P fa3c25ddb9714878b0c81f388fc9e542 reported cstate change: term changed from 0 to 1, leader changed from <none> to fa3c25ddb9714878b0c81f388fc9e542 (127.20.212.129). New cstate: current_term: 1 leader_uuid: "fa3c25ddb9714878b0c81f388fc9e542" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "fa3c25ddb9714878b0c81f388fc9e542" member_type: VOTER last_known_addr { host: "127.20.212.129" port: 41645 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:46.375221 21330 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.054s	user 0.010s	sys 0.012s
I20260812 06:16:46.529975 21914 maintenance_manager.cc:419] P fa3c25ddb9714878b0c81f388fc9e542: Scheduling FlushMRSOp(32cd746a463144e19cdc78282ebfb81a): perf score=19.054940
I20260812 06:16:46.689389 21815 maintenance_manager.cc:643] P fa3c25ddb9714878b0c81f388fc9e542: FlushMRSOp(32cd746a463144e19cdc78282ebfb81a) complete. Timing: real 0.159s	user 0.126s	sys 0.032s Metrics: {"bytes_written":12307489,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":93,"dirs.run_cpu_time_us":171,"dirs.run_wall_time_us":1114,"drs_written":1,"lbm_read_time_us":76,"lbm_reads_lt_1ms":4,"lbm_write_time_us":40498,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":896,"update_count":1500}
I20260812 06:16:46.690207 21914 maintenance_manager.cc:419] P fa3c25ddb9714878b0c81f388fc9e542: Scheduling LogGCOp(32cd746a463144e19cdc78282ebfb81a): free 20290830 bytes of WAL
I20260812 06:16:46.690439 21815 log_reader.cc:385] T 32cd746a463144e19cdc78282ebfb81a: removed 2 log segments from log reader
I20260812 06:16:46.690498 21815 log.cc:1079] T 32cd746a463144e19cdc78282ebfb81a P fa3c25ddb9714878b0c81f388fc9e542: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/32cd746a463144e19cdc78282ebfb81a/wal-000000001 (ops 1-6)
I20260812 06:16:46.690539 21815 log.cc:1079] T 32cd746a463144e19cdc78282ebfb81a P fa3c25ddb9714878b0c81f388fc9e542: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/32cd746a463144e19cdc78282ebfb81a/wal-000000002 (ops 7-10)
I20260812 06:16:46.695273 21815 maintenance_manager.cc:643] P fa3c25ddb9714878b0c81f388fc9e542: LogGCOp(32cd746a463144e19cdc78282ebfb81a) complete. Timing: real 0.005s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:16:46.695595 21914 maintenance_manager.cc:419] P fa3c25ddb9714878b0c81f388fc9e542: Scheduling FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a): perf score=3.181125
I20260812 06:16:46.714030 21815 maintenance_manager.cc:643] P fa3c25ddb9714878b0c81f388fc9e542: FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a) complete. Timing: real 0.018s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4749,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:46.714448 21914 maintenance_manager.cc:419] P fa3c25ddb9714878b0c81f388fc9e542: Scheduling FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a): perf score=2.188937
I20260812 06:16:46.723846 21815 maintenance_manager.cc:643] P fa3c25ddb9714878b0c81f388fc9e542: FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a) complete. Timing: real 0.009s	user 0.003s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3531,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:46.724324 21914 maintenance_manager.cc:419] P fa3c25ddb9714878b0c81f388fc9e542: Scheduling MajorDeltaCompactionOp(32cd746a463144e19cdc78282ebfb81a): perf score=1.000000
I20260812 06:16:46.925427 21815 maintenance_manager.cc:643] P fa3c25ddb9714878b0c81f388fc9e542: MajorDeltaCompactionOp(32cd746a463144e19cdc78282ebfb81a) complete. Timing: real 0.201s	user 0.135s	sys 0.053s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774797,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":615,"lbm_read_time_us":13472,"lbm_reads_lt_1ms":573,"lbm_write_time_us":28712,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6528,"thread_start_us":337,"threads_started":5,"update_count":2500}
I20260812 06:16:46.925947 21914 maintenance_manager.cc:419] P fa3c25ddb9714878b0c81f388fc9e542: Scheduling FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a): perf score=14.095187
I20260812 06:16:46.980731 21815 maintenance_manager.cc:643] P fa3c25ddb9714878b0c81f388fc9e542: FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a) complete. Timing: real 0.055s	user 0.024s	sys 0.028s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":22722,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:16:46.981187 21914 maintenance_manager.cc:419] P fa3c25ddb9714878b0c81f388fc9e542: Scheduling FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a): perf score=2.188937
I20260812 06:16:46.991742 21815 maintenance_manager.cc:643] P fa3c25ddb9714878b0c81f388fc9e542: FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3967,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:46.992318 21914 maintenance_manager.cc:419] P fa3c25ddb9714878b0c81f388fc9e542: Scheduling MajorDeltaCompactionOp(32cd746a463144e19cdc78282ebfb81a): perf score=1.000000
I20260812 06:16:47.144719 21815 maintenance_manager.cc:643] P fa3c25ddb9714878b0c81f388fc9e542: MajorDeltaCompactionOp(32cd746a463144e19cdc78282ebfb81a) complete. Timing: real 0.152s	user 0.108s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":328,"lbm_read_time_us":12221,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27214,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7808,"update_count":2500}
I20260812 06:16:47.145432 21914 maintenance_manager.cc:419] P fa3c25ddb9714878b0c81f388fc9e542: Scheduling UndoDeltaBlockGCOp(32cd746a463144e19cdc78282ebfb81a): 16411395 bytes on disk
I20260812 06:16:47.145843 21815 maintenance_manager.cc:643] P fa3c25ddb9714878b0c81f388fc9e542: UndoDeltaBlockGCOp(32cd746a463144e19cdc78282ebfb81a) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":46,"lbm_reads_lt_1ms":4}
I20260812 06:16:47.146291 21914 maintenance_manager.cc:419] P fa3c25ddb9714878b0c81f388fc9e542: Scheduling FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a): perf score=10.126437
I20260812 06:16:47.183271 21815 maintenance_manager.cc:643] P fa3c25ddb9714878b0c81f388fc9e542: FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a) complete. Timing: real 0.037s	user 0.025s	sys 0.008s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16209,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:47.183888 21914 maintenance_manager.cc:419] P fa3c25ddb9714878b0c81f388fc9e542: Scheduling FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a): perf score=2.188937
I20260812 06:16:47.214867 21815 maintenance_manager.cc:643] P fa3c25ddb9714878b0c81f388fc9e542: FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a) complete. Timing: real 0.031s	user 0.014s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7017,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:47.215384 21914 maintenance_manager.cc:419] P fa3c25ddb9714878b0c81f388fc9e542: Scheduling FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a): perf score=2.188937
I20260812 06:16:47.230033 21815 maintenance_manager.cc:643] P fa3c25ddb9714878b0c81f388fc9e542: FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a) complete. Timing: real 0.014s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5635,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:47.230612 21914 maintenance_manager.cc:419] P fa3c25ddb9714878b0c81f388fc9e542: Scheduling MajorDeltaCompactionOp(32cd746a463144e19cdc78282ebfb81a): perf score=1.000000
I20260812 06:16:47.402503 21815 maintenance_manager.cc:643] P fa3c25ddb9714878b0c81f388fc9e542: MajorDeltaCompactionOp(32cd746a463144e19cdc78282ebfb81a) complete. Timing: real 0.172s	user 0.120s	sys 0.044s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774806,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":154,"lbm_read_time_us":12214,"lbm_reads_lt_1ms":573,"lbm_write_time_us":31648,"lbm_writes_lt_1ms":543,"mutex_wait_us":21,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13952,"update_count":2500}
I20260812 06:16:47.403301 21914 maintenance_manager.cc:419] P fa3c25ddb9714878b0c81f388fc9e542: Scheduling FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a): perf score=14.095187
I20260812 06:16:47.452479 21815 maintenance_manager.cc:643] P fa3c25ddb9714878b0c81f388fc9e542: FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a) complete. Timing: real 0.049s	user 0.029s	sys 0.019s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21640,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:47.452986 21914 maintenance_manager.cc:419] P fa3c25ddb9714878b0c81f388fc9e542: Scheduling FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a): perf score=2.188937
I20260812 06:16:47.465025 21815 maintenance_manager.cc:643] P fa3c25ddb9714878b0c81f388fc9e542: FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4641,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:47.465467 21914 maintenance_manager.cc:419] P fa3c25ddb9714878b0c81f388fc9e542: Scheduling MajorDeltaCompactionOp(32cd746a463144e19cdc78282ebfb81a): perf score=1.000000
I20260812 06:16:47.609542 21815 maintenance_manager.cc:643] P fa3c25ddb9714878b0c81f388fc9e542: MajorDeltaCompactionOp(32cd746a463144e19cdc78282ebfb81a) complete. Timing: real 0.144s	user 0.123s	sys 0.015s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":248,"lbm_read_time_us":9860,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28213,"lbm_writes_lt_1ms":543,"mutex_wait_us":91,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13952,"update_count":2500}
I20260812 06:16:47.610307 21914 maintenance_manager.cc:419] P fa3c25ddb9714878b0c81f388fc9e542: Scheduling FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a): perf score=14.095187
I20260812 06:16:47.670717 21815 maintenance_manager.cc:643] P fa3c25ddb9714878b0c81f388fc9e542: FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a) complete. Timing: real 0.060s	user 0.038s	sys 0.020s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":27920,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:16:47.671262 21914 maintenance_manager.cc:419] P fa3c25ddb9714878b0c81f388fc9e542: Scheduling FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a): perf score=2.188937
I20260812 06:16:47.685513 21815 maintenance_manager.cc:643] P fa3c25ddb9714878b0c81f388fc9e542: FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a) complete. Timing: real 0.014s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4913,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:47.685959 21914 maintenance_manager.cc:419] P fa3c25ddb9714878b0c81f388fc9e542: Scheduling MajorDeltaCompactionOp(32cd746a463144e19cdc78282ebfb81a): perf score=1.000000
I20260812 06:16:47.850303 21815 maintenance_manager.cc:643] P fa3c25ddb9714878b0c81f388fc9e542: MajorDeltaCompactionOp(32cd746a463144e19cdc78282ebfb81a) complete. Timing: real 0.164s	user 0.130s	sys 0.028s 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":181,"lbm_read_time_us":9873,"lbm_reads_lt_1ms":564,"lbm_write_time_us":29893,"lbm_writes_lt_1ms":543,"mutex_wait_us":103,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5632,"update_count":2500}
I20260812 06:16:47.850968 21914 maintenance_manager.cc:419] P fa3c25ddb9714878b0c81f388fc9e542: Scheduling FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a): perf score=14.095187
I20260812 06:16:47.905138 21815 maintenance_manager.cc:643] P fa3c25ddb9714878b0c81f388fc9e542: FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a) complete. Timing: real 0.054s	user 0.037s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24392,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:47.905608 21914 maintenance_manager.cc:419] P fa3c25ddb9714878b0c81f388fc9e542: Scheduling FlushMRSOp(32cd746a463144e19cdc78282ebfb81a): perf score=1.000000
I20260812 06:16:47.935688 21815 maintenance_manager.cc:643] P fa3c25ddb9714878b0c81f388fc9e542: FlushMRSOp(32cd746a463144e19cdc78282ebfb81a) complete. Timing: real 0.030s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":65,"dirs.run_cpu_time_us":264,"dirs.run_wall_time_us":1359,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1433,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:16:47.936321 21914 maintenance_manager.cc:419] P fa3c25ddb9714878b0c81f388fc9e542: Scheduling LogGCOp(32cd746a463144e19cdc78282ebfb81a): free 121006424 bytes of WAL
I20260812 06:16:47.936544 21815 log_reader.cc:385] T 32cd746a463144e19cdc78282ebfb81a: removed 12 log segments from log reader
I20260812 06:16:47.936589 21815 log.cc:1079] T 32cd746a463144e19cdc78282ebfb81a P fa3c25ddb9714878b0c81f388fc9e542: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/32cd746a463144e19cdc78282ebfb81a/wal-000000003 (ops 11-15)
I20260812 06:16:47.936619 21815 log.cc:1079] T 32cd746a463144e19cdc78282ebfb81a P fa3c25ddb9714878b0c81f388fc9e542: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/32cd746a463144e19cdc78282ebfb81a/wal-000000004 (ops 16-20)
I20260812 06:16:47.936682 21815 log.cc:1079] T 32cd746a463144e19cdc78282ebfb81a P fa3c25ddb9714878b0c81f388fc9e542: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/32cd746a463144e19cdc78282ebfb81a/wal-000000005 (ops 21-25)
I20260812 06:16:47.936743 21815 log.cc:1079] T 32cd746a463144e19cdc78282ebfb81a P fa3c25ddb9714878b0c81f388fc9e542: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/32cd746a463144e19cdc78282ebfb81a/wal-000000006 (ops 26-30)
I20260812 06:16:47.936782 21815 log.cc:1079] T 32cd746a463144e19cdc78282ebfb81a P fa3c25ddb9714878b0c81f388fc9e542: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/32cd746a463144e19cdc78282ebfb81a/wal-000000007 (ops 31-34)
I20260812 06:16:47.936825 21815 log.cc:1079] T 32cd746a463144e19cdc78282ebfb81a P fa3c25ddb9714878b0c81f388fc9e542: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/32cd746a463144e19cdc78282ebfb81a/wal-000000008 (ops 35-39)
I20260812 06:16:47.936864 21815 log.cc:1079] T 32cd746a463144e19cdc78282ebfb81a P fa3c25ddb9714878b0c81f388fc9e542: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/32cd746a463144e19cdc78282ebfb81a/wal-000000009 (ops 40-44)
I20260812 06:16:47.936902 21815 log.cc:1079] T 32cd746a463144e19cdc78282ebfb81a P fa3c25ddb9714878b0c81f388fc9e542: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/32cd746a463144e19cdc78282ebfb81a/wal-000000010 (ops 45-49)
I20260812 06:16:47.936944 21815 log.cc:1079] T 32cd746a463144e19cdc78282ebfb81a P fa3c25ddb9714878b0c81f388fc9e542: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/32cd746a463144e19cdc78282ebfb81a/wal-000000011 (ops 50-54)
I20260812 06:16:47.936983 21815 log.cc:1079] T 32cd746a463144e19cdc78282ebfb81a P fa3c25ddb9714878b0c81f388fc9e542: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/32cd746a463144e19cdc78282ebfb81a/wal-000000012 (ops 55-59)
I20260812 06:16:47.937022 21815 log.cc:1079] T 32cd746a463144e19cdc78282ebfb81a P fa3c25ddb9714878b0c81f388fc9e542: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/32cd746a463144e19cdc78282ebfb81a/wal-000000013 (ops 60-64)
I20260812 06:16:47.937059 21815 log.cc:1079] T 32cd746a463144e19cdc78282ebfb81a P fa3c25ddb9714878b0c81f388fc9e542: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/32cd746a463144e19cdc78282ebfb81a/wal-000000014 (ops 65-69)
I20260812 06:16:47.964599 21815 maintenance_manager.cc:643] P fa3c25ddb9714878b0c81f388fc9e542: LogGCOp(32cd746a463144e19cdc78282ebfb81a) complete. Timing: real 0.028s	user 0.000s	sys 0.028s Metrics: {}
I20260812 06:16:47.964987 21914 maintenance_manager.cc:419] P fa3c25ddb9714878b0c81f388fc9e542: Scheduling FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a): perf score=5.165500
I20260812 06:16:47.984499 21815 maintenance_manager.cc:643] P fa3c25ddb9714878b0c81f388fc9e542: FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a) complete. Timing: real 0.019s	user 0.015s	sys 0.004s Metrics: {"bytes_written":6523087,"delete_count":0,"lbm_write_time_us":7752,"lbm_writes_lt_1ms":162,"reinsert_count":0,"update_count":795}
I20260812 06:16:47.984941 21914 maintenance_manager.cc:419] P fa3c25ddb9714878b0c81f388fc9e542: Scheduling UndoDeltaBlockGCOp(32cd746a463144e19cdc78282ebfb81a): 472 bytes on disk
I20260812 06:16:47.985399 21815 maintenance_manager.cc:643] P fa3c25ddb9714878b0c81f388fc9e542: UndoDeltaBlockGCOp(32cd746a463144e19cdc78282ebfb81a) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":68,"lbm_reads_lt_1ms":4}
I20260812 06:16:47.985842 21914 maintenance_manager.cc:419] P fa3c25ddb9714878b0c81f388fc9e542: Scheduling FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a): perf score=1.000000
I20260812 06:16:47.996565 21815 maintenance_manager.cc:643] P fa3c25ddb9714878b0c81f388fc9e542: FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":1682177,"delete_count":0,"lbm_write_time_us":2932,"lbm_writes_lt_1ms":44,"reinsert_count":0,"update_count":205}
I20260812 06:16:47.997090 21914 maintenance_manager.cc:419] P fa3c25ddb9714878b0c81f388fc9e542: Scheduling MajorDeltaCompactionOp(32cd746a463144e19cdc78282ebfb81a): perf score=1.000000
I20260812 06:16:48.216385 21815 maintenance_manager.cc:643] P fa3c25ddb9714878b0c81f388fc9e542: MajorDeltaCompactionOp(32cd746a463144e19cdc78282ebfb81a) complete. Timing: real 0.219s	user 0.158s	sys 0.060s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877160,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":753,"lbm_read_time_us":15195,"lbm_reads_lt_1ms":665,"lbm_write_time_us":37772,"lbm_writes_lt_1ms":643,"mutex_wait_us":59,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":4096,"thread_start_us":107,"threads_started":1,"update_count":3000}
I20260812 06:16:48.217374 21914 maintenance_manager.cc:419] P fa3c25ddb9714878b0c81f388fc9e542: Scheduling FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a): perf score=14.095187
I20260812 06:16:48.274966 21815 maintenance_manager.cc:643] P fa3c25ddb9714878b0c81f388fc9e542: FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a) complete. Timing: real 0.057s	user 0.030s	sys 0.021s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22384,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:16:48.275480 21914 maintenance_manager.cc:419] P fa3c25ddb9714878b0c81f388fc9e542: Scheduling FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a): perf score=2.188937
I20260812 06:16:48.286669 21815 maintenance_manager.cc:643] P fa3c25ddb9714878b0c81f388fc9e542: FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3975,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:48.287139 21914 maintenance_manager.cc:419] P fa3c25ddb9714878b0c81f388fc9e542: Scheduling MajorDeltaCompactionOp(32cd746a463144e19cdc78282ebfb81a): perf score=1.000000
I20260812 06:16:48.493014 21815 maintenance_manager.cc:643] P fa3c25ddb9714878b0c81f388fc9e542: MajorDeltaCompactionOp(32cd746a463144e19cdc78282ebfb81a) complete. Timing: real 0.206s	user 0.162s	sys 0.043s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":534,"lbm_read_time_us":12299,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32960,"lbm_writes_lt_1ms":543,"mutex_wait_us":267,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6400,"update_count":2500}
I20260812 06:16:48.493657 21914 maintenance_manager.cc:419] P fa3c25ddb9714878b0c81f388fc9e542: Scheduling FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a): perf score=14.095187
I20260812 06:16:48.550889 21815 maintenance_manager.cc:643] P fa3c25ddb9714878b0c81f388fc9e542: FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a) complete. Timing: real 0.057s	user 0.029s	sys 0.024s Metrics: {"bytes_written":16409897,"delete_count":0,"lbm_write_time_us":26839,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:16:48.551400 21914 maintenance_manager.cc:419] P fa3c25ddb9714878b0c81f388fc9e542: Scheduling FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a): perf score=2.188937
I20260812 06:16:48.567755 21815 maintenance_manager.cc:643] P fa3c25ddb9714878b0c81f388fc9e542: FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a) complete. Timing: real 0.016s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5912,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:48.568289 21914 maintenance_manager.cc:419] P fa3c25ddb9714878b0c81f388fc9e542: Scheduling MajorDeltaCompactionOp(32cd746a463144e19cdc78282ebfb81a): perf score=1.000000
I20260812 06:16:48.750370 21815 maintenance_manager.cc:643] P fa3c25ddb9714878b0c81f388fc9e542: MajorDeltaCompactionOp(32cd746a463144e19cdc78282ebfb81a) complete. Timing: real 0.182s	user 0.133s	sys 0.049s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774684,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":994,"lbm_read_time_us":13731,"lbm_reads_lt_1ms":568,"lbm_write_time_us":30384,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":2500}
I20260812 06:16:48.751001 21914 maintenance_manager.cc:419] P fa3c25ddb9714878b0c81f388fc9e542: Scheduling FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a): perf score=14.095187
I20260812 06:16:48.812294 21815 maintenance_manager.cc:643] P fa3c25ddb9714878b0c81f388fc9e542: FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a) complete. Timing: real 0.061s	user 0.034s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19264,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:48.813119 21914 maintenance_manager.cc:419] P fa3c25ddb9714878b0c81f388fc9e542: Scheduling FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a): perf score=2.188937
I20260812 06:16:48.832576 21815 maintenance_manager.cc:643] P fa3c25ddb9714878b0c81f388fc9e542: FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a) complete. Timing: real 0.019s	user 0.011s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7292,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:48.833271 21914 maintenance_manager.cc:419] P fa3c25ddb9714878b0c81f388fc9e542: Scheduling MajorDeltaCompactionOp(32cd746a463144e19cdc78282ebfb81a): perf score=1.000000
I20260812 06:16:49.044761 21815 maintenance_manager.cc:643] P fa3c25ddb9714878b0c81f388fc9e542: MajorDeltaCompactionOp(32cd746a463144e19cdc78282ebfb81a) complete. Timing: real 0.211s	user 0.135s	sys 0.076s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1150,"lbm_read_time_us":17695,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34068,"lbm_writes_lt_1ms":543,"mutex_wait_us":334,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:16:49.045523 21914 maintenance_manager.cc:419] P fa3c25ddb9714878b0c81f388fc9e542: Scheduling FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a): perf score=14.095187
I20260812 06:16:49.104835 21815 maintenance_manager.cc:643] P fa3c25ddb9714878b0c81f388fc9e542: FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a) complete. Timing: real 0.059s	user 0.022s	sys 0.031s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19004,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:49.105372 21914 maintenance_manager.cc:419] P fa3c25ddb9714878b0c81f388fc9e542: Scheduling FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a): perf score=2.188937
I20260812 06:16:49.115797 21815 maintenance_manager.cc:643] P fa3c25ddb9714878b0c81f388fc9e542: FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4122,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:49.116257 21914 maintenance_manager.cc:419] P fa3c25ddb9714878b0c81f388fc9e542: Scheduling MajorDeltaCompactionOp(32cd746a463144e19cdc78282ebfb81a): perf score=1.000000
I20260812 06:16:49.298236 21815 maintenance_manager.cc:643] P fa3c25ddb9714878b0c81f388fc9e542: MajorDeltaCompactionOp(32cd746a463144e19cdc78282ebfb81a) complete. Timing: real 0.182s	user 0.124s	sys 0.057s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1004,"lbm_read_time_us":14321,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28812,"lbm_writes_lt_1ms":543,"mutex_wait_us":250,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5120,"update_count":2500}
I20260812 06:16:49.298905 21914 maintenance_manager.cc:419] P fa3c25ddb9714878b0c81f388fc9e542: Scheduling FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a): perf score=11.118625
I20260812 06:16:49.338332 21815 maintenance_manager.cc:643] P fa3c25ddb9714878b0c81f388fc9e542: FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a) complete. Timing: real 0.039s	user 0.034s	sys 0.003s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16507,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:49.338827 21914 maintenance_manager.cc:419] P fa3c25ddb9714878b0c81f388fc9e542: Scheduling FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a): perf score=2.188937
I20260812 06:16:49.351692 21815 maintenance_manager.cc:643] P fa3c25ddb9714878b0c81f388fc9e542: FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a) complete. Timing: real 0.013s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3728,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:49.352264 21914 maintenance_manager.cc:419] P fa3c25ddb9714878b0c81f388fc9e542: Scheduling MajorDeltaCompactionOp(32cd746a463144e19cdc78282ebfb81a): perf score=1.000000
I20260812 06:16:49.487601 21815 maintenance_manager.cc:643] P fa3c25ddb9714878b0c81f388fc9e542: MajorDeltaCompactionOp(32cd746a463144e19cdc78282ebfb81a) complete. Timing: real 0.135s	user 0.092s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":705,"lbm_read_time_us":8595,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26378,"lbm_writes_lt_1ms":443,"mutex_wait_us":33,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":17536,"update_count":2000}
I20260812 06:16:49.489303 21914 maintenance_manager.cc:419] P fa3c25ddb9714878b0c81f388fc9e542: Scheduling FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a): perf score=10.126437
I20260812 06:16:49.525157 21815 maintenance_manager.cc:643] P fa3c25ddb9714878b0c81f388fc9e542: FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a) complete. Timing: real 0.036s	user 0.018s	sys 0.016s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15650,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:16:49.525671 21914 maintenance_manager.cc:419] P fa3c25ddb9714878b0c81f388fc9e542: Scheduling FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a): perf score=2.188937
I20260812 06:16:49.542423 21815 maintenance_manager.cc:643] P fa3c25ddb9714878b0c81f388fc9e542: FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a) complete. Timing: real 0.017s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5862,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:49.542959 21914 maintenance_manager.cc:419] P fa3c25ddb9714878b0c81f388fc9e542: Scheduling FlushMRSOp(32cd746a463144e19cdc78282ebfb81a): perf score=1.000000
I20260812 06:16:49.595022 21815 maintenance_manager.cc:643] P fa3c25ddb9714878b0c81f388fc9e542: FlushMRSOp(32cd746a463144e19cdc78282ebfb81a) complete. Timing: real 0.052s	user 0.021s	sys 0.008s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":83,"dirs.run_cpu_time_us":219,"dirs.run_wall_time_us":1297,"drs_written":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2419,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30,"spinlock_wait_cycles":9600}
I20260812 06:16:49.595727 21914 maintenance_manager.cc:419] P fa3c25ddb9714878b0c81f388fc9e542: Scheduling LogGCOp(32cd746a463144e19cdc78282ebfb81a): free 124257256 bytes of WAL
I20260812 06:16:49.595965 21815 log_reader.cc:385] T 32cd746a463144e19cdc78282ebfb81a: removed 12 log segments from log reader
I20260812 06:16:49.596014 21815 log.cc:1079] T 32cd746a463144e19cdc78282ebfb81a P fa3c25ddb9714878b0c81f388fc9e542: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/32cd746a463144e19cdc78282ebfb81a/wal-000000015 (ops 70-74)
I20260812 06:16:49.596072 21815 log.cc:1079] T 32cd746a463144e19cdc78282ebfb81a P fa3c25ddb9714878b0c81f388fc9e542: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/32cd746a463144e19cdc78282ebfb81a/wal-000000016 (ops 75-78)
I20260812 06:16:49.596146 21815 log.cc:1079] T 32cd746a463144e19cdc78282ebfb81a P fa3c25ddb9714878b0c81f388fc9e542: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/32cd746a463144e19cdc78282ebfb81a/wal-000000017 (ops 79-83)
I20260812 06:16:49.596215 21815 log.cc:1079] T 32cd746a463144e19cdc78282ebfb81a P fa3c25ddb9714878b0c81f388fc9e542: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/32cd746a463144e19cdc78282ebfb81a/wal-000000018 (ops 84-88)
I20260812 06:16:49.596257 21815 log.cc:1079] T 32cd746a463144e19cdc78282ebfb81a P fa3c25ddb9714878b0c81f388fc9e542: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/32cd746a463144e19cdc78282ebfb81a/wal-000000019 (ops 89-93)
I20260812 06:16:49.596297 21815 log.cc:1079] T 32cd746a463144e19cdc78282ebfb81a P fa3c25ddb9714878b0c81f388fc9e542: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/32cd746a463144e19cdc78282ebfb81a/wal-000000020 (ops 94-98)
I20260812 06:16:49.596336 21815 log.cc:1079] T 32cd746a463144e19cdc78282ebfb81a P fa3c25ddb9714878b0c81f388fc9e542: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/32cd746a463144e19cdc78282ebfb81a/wal-000000021 (ops 99-103)
I20260812 06:16:49.596375 21815 log.cc:1079] T 32cd746a463144e19cdc78282ebfb81a P fa3c25ddb9714878b0c81f388fc9e542: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/32cd746a463144e19cdc78282ebfb81a/wal-000000022 (ops 104-108)
I20260812 06:16:49.596414 21815 log.cc:1079] T 32cd746a463144e19cdc78282ebfb81a P fa3c25ddb9714878b0c81f388fc9e542: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/32cd746a463144e19cdc78282ebfb81a/wal-000000023 (ops 109-113)
I20260812 06:16:49.596453 21815 log.cc:1079] T 32cd746a463144e19cdc78282ebfb81a P fa3c25ddb9714878b0c81f388fc9e542: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/32cd746a463144e19cdc78282ebfb81a/wal-000000024 (ops 114-118)
I20260812 06:16:49.596493 21815 log.cc:1079] T 32cd746a463144e19cdc78282ebfb81a P fa3c25ddb9714878b0c81f388fc9e542: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/32cd746a463144e19cdc78282ebfb81a/wal-000000025 (ops 119-123)
I20260812 06:16:49.596535 21815 log.cc:1079] T 32cd746a463144e19cdc78282ebfb81a P fa3c25ddb9714878b0c81f388fc9e542: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/32cd746a463144e19cdc78282ebfb81a/wal-000000026 (ops 124-128)
I20260812 06:16:49.622223 21815 maintenance_manager.cc:643] P fa3c25ddb9714878b0c81f388fc9e542: LogGCOp(32cd746a463144e19cdc78282ebfb81a) complete. Timing: real 0.026s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:16:49.622723 21914 maintenance_manager.cc:419] P fa3c25ddb9714878b0c81f388fc9e542: Scheduling FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a): perf score=7.149875
I20260812 06:16:49.642621 21815 maintenance_manager.cc:643] P fa3c25ddb9714878b0c81f388fc9e542: FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a) complete. Timing: real 0.020s	user 0.009s	sys 0.008s Metrics: {"bytes_written":8615324,"delete_count":0,"lbm_write_time_us":8611,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:16:49.643086 21914 maintenance_manager.cc:419] P fa3c25ddb9714878b0c81f388fc9e542: Scheduling FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a): perf score=2.188937
I20260812 06:16:49.661582 21815 maintenance_manager.cc:643] P fa3c25ddb9714878b0c81f388fc9e542: FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a) complete. Timing: real 0.018s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5184,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:49.662132 21914 maintenance_manager.cc:419] P fa3c25ddb9714878b0c81f388fc9e542: Scheduling MajorDeltaCompactionOp(32cd746a463144e19cdc78282ebfb81a): perf score=1.000000
I20260812 06:16:49.880692 21815 maintenance_manager.cc:643] P fa3c25ddb9714878b0c81f388fc9e542: MajorDeltaCompactionOp(32cd746a463144e19cdc78282ebfb81a) complete. Timing: real 0.218s	user 0.150s	sys 0.063s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979742,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":5587,"lbm_read_time_us":15238,"lbm_reads_lt_1ms":766,"lbm_write_time_us":38885,"lbm_writes_lt_1ms":743,"mutex_wait_us":2713,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":1664,"thread_start_us":88,"threads_started":1,"update_count":3500}
I20260812 06:16:49.881521 21914 maintenance_manager.cc:419] P fa3c25ddb9714878b0c81f388fc9e542: Scheduling UndoDeltaBlockGCOp(32cd746a463144e19cdc78282ebfb81a): 472 bytes on disk
I20260812 06:16:49.882416 21815 maintenance_manager.cc:643] P fa3c25ddb9714878b0c81f388fc9e542: UndoDeltaBlockGCOp(32cd746a463144e19cdc78282ebfb81a) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4}
I20260812 06:16:49.882997 21914 maintenance_manager.cc:419] P fa3c25ddb9714878b0c81f388fc9e542: Scheduling FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a): perf score=18.063937
I20260812 06:16:49.962390 21815 maintenance_manager.cc:643] P fa3c25ddb9714878b0c81f388fc9e542: FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a) complete. Timing: real 0.079s	user 0.032s	sys 0.043s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":30244,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":502,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2500}
I20260812 06:16:49.963107 21914 maintenance_manager.cc:419] P fa3c25ddb9714878b0c81f388fc9e542: Scheduling FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a): perf score=4.173312
I20260812 06:16:49.982702 21815 maintenance_manager.cc:643] P fa3c25ddb9714878b0c81f388fc9e542: FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a) complete. Timing: real 0.019s	user 0.012s	sys 0.004s Metrics: {"bytes_written":6400018,"delete_count":0,"lbm_write_time_us":7918,"lbm_writes_lt_1ms":159,"reinsert_count":0,"update_count":780}
I20260812 06:16:49.983295 21914 maintenance_manager.cc:419] P fa3c25ddb9714878b0c81f388fc9e542: Scheduling FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a): perf score=1.000000
I20260812 06:16:49.993146 21815 maintenance_manager.cc:643] P fa3c25ddb9714878b0c81f388fc9e542: FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":1805252,"delete_count":0,"lbm_write_time_us":2979,"lbm_writes_lt_1ms":47,"reinsert_count":0,"update_count":220}
I20260812 06:16:49.993907 21914 maintenance_manager.cc:419] P fa3c25ddb9714878b0c81f388fc9e542: Scheduling MajorDeltaCompactionOp(32cd746a463144e19cdc78282ebfb81a): perf score=1.000000
I20260812 06:16:50.239568 21815 maintenance_manager.cc:643] P fa3c25ddb9714878b0c81f388fc9e542: MajorDeltaCompactionOp(32cd746a463144e19cdc78282ebfb81a) complete. Timing: real 0.245s	user 0.129s	sys 0.108s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":32979581,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1188,"lbm_read_time_us":16726,"lbm_reads_lt_1ms":773,"lbm_write_time_us":41876,"lbm_writes_lt_1ms":743,"mutex_wait_us":333,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":25856,"update_count":3500}
I20260812 06:16:50.240296 21914 maintenance_manager.cc:419] P fa3c25ddb9714878b0c81f388fc9e542: Scheduling FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a): perf score=18.063937
I20260812 06:16:50.314121 21815 maintenance_manager.cc:643] P fa3c25ddb9714878b0c81f388fc9e542: FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a) complete. Timing: real 0.074s	user 0.034s	sys 0.036s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":34139,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":501,"reinsert_count":0,"update_count":2500}
I20260812 06:16:50.314594 21914 maintenance_manager.cc:419] P fa3c25ddb9714878b0c81f388fc9e542: Scheduling FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a): perf score=2.188937
I20260812 06:16:50.328773 21815 maintenance_manager.cc:643] P fa3c25ddb9714878b0c81f388fc9e542: FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a) complete. Timing: real 0.014s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5210,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:50.329408 21914 maintenance_manager.cc:419] P fa3c25ddb9714878b0c81f388fc9e542: Scheduling MajorDeltaCompactionOp(32cd746a463144e19cdc78282ebfb81a): perf score=1.000000
I20260812 06:16:50.536881 21815 maintenance_manager.cc:643] P fa3c25ddb9714878b0c81f388fc9e542: MajorDeltaCompactionOp(32cd746a463144e19cdc78282ebfb81a) complete. Timing: real 0.207s	user 0.124s	sys 0.080s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877102,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":366,"lbm_read_time_us":14717,"lbm_reads_lt_1ms":672,"lbm_write_time_us":35725,"lbm_writes_lt_1ms":643,"mutex_wait_us":42,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:16:50.537845 21914 maintenance_manager.cc:419] P fa3c25ddb9714878b0c81f388fc9e542: Scheduling FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a): perf score=16.079562
I20260812 06:16:50.590478 21815 maintenance_manager.cc:643] P fa3c25ddb9714878b0c81f388fc9e542: FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a) complete. Timing: real 0.052s	user 0.036s	sys 0.012s Metrics: {"bytes_written":17845750,"delete_count":0,"lbm_write_time_us":22163,"lbm_writes_lt_1ms":438,"reinsert_count":0,"update_count":2175}
I20260812 06:16:50.591122 21914 maintenance_manager.cc:419] P fa3c25ddb9714878b0c81f388fc9e542: Scheduling FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a): perf score=1.196750
I20260812 06:16:50.602722 21815 maintenance_manager.cc:643] P fa3c25ddb9714878b0c81f388fc9e542: FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":3159088,"delete_count":0,"lbm_write_time_us":4399,"lbm_writes_lt_1ms":80,"reinsert_count":0,"update_count":385}
I20260812 06:16:50.603256 21914 maintenance_manager.cc:419] P fa3c25ddb9714878b0c81f388fc9e542: Scheduling FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a): perf score=2.188937
I20260812 06:16:50.613857 21815 maintenance_manager.cc:643] P fa3c25ddb9714878b0c81f388fc9e542: FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3610355,"delete_count":0,"lbm_write_time_us":4039,"lbm_writes_lt_1ms":91,"reinsert_count":0,"update_count":440}
I20260812 06:16:50.614454 21914 maintenance_manager.cc:419] P fa3c25ddb9714878b0c81f388fc9e542: Scheduling MajorDeltaCompactionOp(32cd746a463144e19cdc78282ebfb81a): perf score=1.000000
I20260812 06:16:50.827718 21815 maintenance_manager.cc:643] P fa3c25ddb9714878b0c81f388fc9e542: MajorDeltaCompactionOp(32cd746a463144e19cdc78282ebfb81a) complete. Timing: real 0.213s	user 0.115s	sys 0.098s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877193,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":162,"lbm_read_time_us":14387,"lbm_reads_lt_1ms":673,"lbm_write_time_us":36645,"lbm_writes_lt_1ms":643,"mutex_wait_us":71,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":12544,"update_count":3000}
I20260812 06:16:50.828652 21914 maintenance_manager.cc:419] P fa3c25ddb9714878b0c81f388fc9e542: Scheduling FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a): perf score=15.087375
I20260812 06:16:50.877950 21815 maintenance_manager.cc:643] P fa3c25ddb9714878b0c81f388fc9e542: FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a) complete. Timing: real 0.049s	user 0.023s	sys 0.024s Metrics: {"bytes_written":16820144,"delete_count":0,"lbm_write_time_us":19922,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:16:50.878786 21914 maintenance_manager.cc:419] P fa3c25ddb9714878b0c81f388fc9e542: Scheduling FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a): perf score=2.188937
I20260812 06:16:50.894924 21815 maintenance_manager.cc:643] P fa3c25ddb9714878b0c81f388fc9e542: FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a) complete. Timing: real 0.016s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5204,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:50.895474 21914 maintenance_manager.cc:419] P fa3c25ddb9714878b0c81f388fc9e542: Scheduling MajorDeltaCompactionOp(32cd746a463144e19cdc78282ebfb81a): perf score=1.000000
I20260812 06:16:51.072819 21815 maintenance_manager.cc:643] P fa3c25ddb9714878b0c81f388fc9e542: MajorDeltaCompactionOp(32cd746a463144e19cdc78282ebfb81a) complete. Timing: real 0.177s	user 0.122s	sys 0.055s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774677,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":404,"lbm_read_time_us":13488,"lbm_reads_lt_1ms":564,"lbm_write_time_us":31006,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2500}
I20260812 06:16:51.073760 21914 maintenance_manager.cc:419] P fa3c25ddb9714878b0c81f388fc9e542: Scheduling FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a): perf score=14.095187
I20260812 06:16:51.126523 21815 maintenance_manager.cc:643] P fa3c25ddb9714878b0c81f388fc9e542: FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a) complete. Timing: real 0.053s	user 0.041s	sys 0.009s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23920,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:51.127099 21914 maintenance_manager.cc:419] P fa3c25ddb9714878b0c81f388fc9e542: Scheduling FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a): perf score=2.188937
I20260812 06:16:51.143042 21815 maintenance_manager.cc:643] P fa3c25ddb9714878b0c81f388fc9e542: FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a) complete. Timing: real 0.016s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5094,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:51.143584 21914 maintenance_manager.cc:419] P fa3c25ddb9714878b0c81f388fc9e542: Scheduling FlushMRSOp(32cd746a463144e19cdc78282ebfb81a): perf score=1.000000
I20260812 06:16:51.172561 21815 maintenance_manager.cc:643] P fa3c25ddb9714878b0c81f388fc9e542: FlushMRSOp(32cd746a463144e19cdc78282ebfb81a) complete. Timing: real 0.029s	user 0.025s	sys 0.004s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":69,"dirs.run_cpu_time_us":223,"dirs.run_wall_time_us":1284,"drs_written":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1707,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:16:51.173565 21914 maintenance_manager.cc:419] P fa3c25ddb9714878b0c81f388fc9e542: Scheduling LogGCOp(32cd746a463144e19cdc78282ebfb81a): free 128867740 bytes of WAL
I20260812 06:16:51.173838 21815 log_reader.cc:385] T 32cd746a463144e19cdc78282ebfb81a: removed 13 log segments from log reader
I20260812 06:16:51.173909 21815 log.cc:1079] T 32cd746a463144e19cdc78282ebfb81a P fa3c25ddb9714878b0c81f388fc9e542: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/32cd746a463144e19cdc78282ebfb81a/wal-000000027 (ops 129-133)
I20260812 06:16:51.173965 21815 log.cc:1079] T 32cd746a463144e19cdc78282ebfb81a P fa3c25ddb9714878b0c81f388fc9e542: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/32cd746a463144e19cdc78282ebfb81a/wal-000000028 (ops 134-138)
I20260812 06:16:51.174002 21815 log.cc:1079] T 32cd746a463144e19cdc78282ebfb81a P fa3c25ddb9714878b0c81f388fc9e542: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/32cd746a463144e19cdc78282ebfb81a/wal-000000029 (ops 139-143)
I20260812 06:16:51.174036 21815 log.cc:1079] T 32cd746a463144e19cdc78282ebfb81a P fa3c25ddb9714878b0c81f388fc9e542: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/32cd746a463144e19cdc78282ebfb81a/wal-000000030 (ops 144-148)
I20260812 06:16:51.174075 21815 log.cc:1079] T 32cd746a463144e19cdc78282ebfb81a P fa3c25ddb9714878b0c81f388fc9e542: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/32cd746a463144e19cdc78282ebfb81a/wal-000000031 (ops 149-153)
I20260812 06:16:51.174122 21815 log.cc:1079] T 32cd746a463144e19cdc78282ebfb81a P fa3c25ddb9714878b0c81f388fc9e542: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/32cd746a463144e19cdc78282ebfb81a/wal-000000032 (ops 154-158)
I20260812 06:16:51.174161 21815 log.cc:1079] T 32cd746a463144e19cdc78282ebfb81a P fa3c25ddb9714878b0c81f388fc9e542: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/32cd746a463144e19cdc78282ebfb81a/wal-000000033 (ops 159-162)
I20260812 06:16:51.174199 21815 log.cc:1079] T 32cd746a463144e19cdc78282ebfb81a P fa3c25ddb9714878b0c81f388fc9e542: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/32cd746a463144e19cdc78282ebfb81a/wal-000000034 (ops 163-167)
I20260812 06:16:51.174237 21815 log.cc:1079] T 32cd746a463144e19cdc78282ebfb81a P fa3c25ddb9714878b0c81f388fc9e542: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/32cd746a463144e19cdc78282ebfb81a/wal-000000035 (ops 168-172)
I20260812 06:16:51.174275 21815 log.cc:1079] T 32cd746a463144e19cdc78282ebfb81a P fa3c25ddb9714878b0c81f388fc9e542: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/32cd746a463144e19cdc78282ebfb81a/wal-000000036 (ops 173-176)
I20260812 06:16:51.174312 21815 log.cc:1079] T 32cd746a463144e19cdc78282ebfb81a P fa3c25ddb9714878b0c81f388fc9e542: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/32cd746a463144e19cdc78282ebfb81a/wal-000000037 (ops 177-181)
I20260812 06:16:51.174350 21815 log.cc:1079] T 32cd746a463144e19cdc78282ebfb81a P fa3c25ddb9714878b0c81f388fc9e542: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/32cd746a463144e19cdc78282ebfb81a/wal-000000038 (ops 182-186)
I20260812 06:16:51.174388 21815 log.cc:1079] T 32cd746a463144e19cdc78282ebfb81a P fa3c25ddb9714878b0c81f388fc9e542: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/32cd746a463144e19cdc78282ebfb81a/wal-000000039 (ops 187-190)
I20260812 06:16:51.204032 21815 maintenance_manager.cc:643] P fa3c25ddb9714878b0c81f388fc9e542: LogGCOp(32cd746a463144e19cdc78282ebfb81a) complete. Timing: real 0.030s	user 0.001s	sys 0.028s Metrics: {}
I20260812 06:16:51.204522 21914 maintenance_manager.cc:419] P fa3c25ddb9714878b0c81f388fc9e542: Scheduling UndoDeltaBlockGCOp(32cd746a463144e19cdc78282ebfb81a): 493 bytes on disk
I20260812 06:16:51.204955 21815 maintenance_manager.cc:643] P fa3c25ddb9714878b0c81f388fc9e542: UndoDeltaBlockGCOp(32cd746a463144e19cdc78282ebfb81a) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4}
I20260812 06:16:51.205499 21914 maintenance_manager.cc:419] P fa3c25ddb9714878b0c81f388fc9e542: Scheduling FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a): perf score=6.157687
I20260812 06:16:51.232719 21815 maintenance_manager.cc:643] P fa3c25ddb9714878b0c81f388fc9e542: FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a) complete. Timing: real 0.027s	user 0.013s	sys 0.010s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":10260,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:51.233314 21914 maintenance_manager.cc:419] P fa3c25ddb9714878b0c81f388fc9e542: Scheduling LogGCOp(32cd746a463144e19cdc78282ebfb81a): free 8767140 bytes of WAL
I20260812 06:16:51.233613 21815 log_reader.cc:385] T 32cd746a463144e19cdc78282ebfb81a: removed 1 log segments from log reader
I20260812 06:16:51.233685 21815 log.cc:1079] T 32cd746a463144e19cdc78282ebfb81a P fa3c25ddb9714878b0c81f388fc9e542: Deleting log segment in path: /tmp/dist-test-tasks1yr_T/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398952044-21330-0/minicluster-data/ts-0-root/wals/32cd746a463144e19cdc78282ebfb81a/wal-000000040 (ops 191-195)
I20260812 06:16:51.235926 21815 maintenance_manager.cc:643] P fa3c25ddb9714878b0c81f388fc9e542: LogGCOp(32cd746a463144e19cdc78282ebfb81a) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:16:51.236369 21914 maintenance_manager.cc:419] P fa3c25ddb9714878b0c81f388fc9e542: Scheduling MajorDeltaCompactionOp(32cd746a463144e19cdc78282ebfb81a): perf score=1.000000
I20260812 06:16:51.359905 21330 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.985s	user 1.878s	sys 0.153s
I20260812 06:16:51.449426 21815 maintenance_manager.cc:643] P fa3c25ddb9714878b0c81f388fc9e542: MajorDeltaCompactionOp(32cd746a463144e19cdc78282ebfb81a) complete. Timing: real 0.213s	user 0.141s	sys 0.071s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":32979633,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":733,"lbm_read_time_us":16736,"lbm_reads_lt_1ms":761,"lbm_write_time_us":37522,"lbm_writes_lt_1ms":743,"mutex_wait_us":356,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":15360,"thread_start_us":98,"threads_started":1,"update_count":3500}
I20260812 06:16:51.452164 21914 maintenance_manager.cc:419] P fa3c25ddb9714878b0c81f388fc9e542: Scheduling FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a): perf score=10.126437
I20260812 06:16:51.458631 21330 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.098s	user 0.001s	sys 0.000s
I20260812 06:16:51.459183 21330 tablet_server.cc:179] TabletServer@127.20.212.129:0 shutting down...
I20260812 06:16:51.490440 21815 maintenance_manager.cc:643] P fa3c25ddb9714878b0c81f388fc9e542: FlushDeltaMemStoresOp(32cd746a463144e19cdc78282ebfb81a) complete. Timing: real 0.038s	user 0.018s	sys 0.017s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16004,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:51.491282 21330 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:16:51.491590 21330 tablet_replica.cc:333] T 32cd746a463144e19cdc78282ebfb81a P fa3c25ddb9714878b0c81f388fc9e542: stopping tablet replica
I20260812 06:16:51.491734 21330 raft_consensus.cc:2243] T 32cd746a463144e19cdc78282ebfb81a P fa3c25ddb9714878b0c81f388fc9e542 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:51.491905 21330 raft_consensus.cc:2272] T 32cd746a463144e19cdc78282ebfb81a P fa3c25ddb9714878b0c81f388fc9e542 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:51.495965 21330 tablet_server.cc:196] TabletServer@127.20.212.129:0 shutdown complete.
I20260812 06:16:51.507681 21330 master.cc:562] Master@127.20.212.190:33991 shutting down...
I20260812 06:16:51.511425 21330 raft_consensus.cc:2243] T 00000000000000000000000000000000 P fbe54774b5c14908bdd7d6c85b5cfeba [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:51.511642 21330 raft_consensus.cc:2272] T 00000000000000000000000000000000 P fbe54774b5c14908bdd7d6c85b5cfeba [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:51.511737 21330 tablet_replica.cc:333] T 00000000000000000000000000000000 P fbe54774b5c14908bdd7d6c85b5cfeba: stopping tablet replica
I20260812 06:16:51.524371 21330 master.cc:584] Master@127.20.212.190:33991 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5492 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (12652 ms total)

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