[==========] 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:18:27.092386 15750 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.15.97.190:40907
I20260812 06:18:27.093549 15750 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:18:27.094249 15750 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:27.101425 15761 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:18:27.101560 15750 server_base.cc:1061] running on GCE node
W20260812 06:18:27.101716 15757 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:18:27.101492 15758 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:18:27.102380 15750 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:27.102519 15750 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:18:27.102588 15750 hybrid_clock.cc:648] HybridClock initialized: now 1786515507102586 us; error 0 us; skew 500 ppm
I20260812 06:18:27.104709 15750 webserver.cc:533] Webserver started at http://127.15.97.190:34913/ using document root <none> and password file <none>
I20260812 06:18:27.105322 15750 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:27.105427 15750 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:27.105722 15750 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:27.107571 15750 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507080306-15750-0/minicluster-data/master-0-root/instance:
uuid: "f9d48da9888e4623b12185280dc0dcb8"
format_stamp: "Formatted at 2026-08-12 06:18:27 on dist-test-slave-27sr"
I20260812 06:18:27.111843 15750 fs_manager.cc:696] Time spent creating directory manager: real 0.004s	user 0.002s	sys 0.001s
I20260812 06:18:27.114390 15768 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:18:27.115573 15750 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:18:27.115742 15750 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507080306-15750-0/minicluster-data/master-0-root
uuid: "f9d48da9888e4623b12185280dc0dcb8"
format_stamp: "Formatted at 2026-08-12 06:18:27 on dist-test-slave-27sr"
I20260812 06:18:27.115870 15750 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507080306-15750-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507080306-15750-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507080306-15750-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:18:27.127499 15750 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:27.128250 15750 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:18:27.128453 15750 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:27.137545 15750 rpc_server.cc:307] RPC server started. Bound to: 127.15.97.190:40907
I20260812 06:18:27.137599 15832 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.15.97.190:40907 every 8 connection(s)
I20260812 06:18:27.140146 15833 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:18:27.145455 15833 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P f9d48da9888e4623b12185280dc0dcb8: Bootstrap starting.
I20260812 06:18:27.147785 15833 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P f9d48da9888e4623b12185280dc0dcb8: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:27.148730 15833 log.cc:826] T 00000000000000000000000000000000 P f9d48da9888e4623b12185280dc0dcb8: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:27.150506 15833 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P f9d48da9888e4623b12185280dc0dcb8: No bootstrap required, opened a new log
I20260812 06:18:27.153241 15833 raft_consensus.cc:359] T 00000000000000000000000000000000 P f9d48da9888e4623b12185280dc0dcb8 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f9d48da9888e4623b12185280dc0dcb8" member_type: VOTER }
I20260812 06:18:27.153409 15833 raft_consensus.cc:385] T 00000000000000000000000000000000 P f9d48da9888e4623b12185280dc0dcb8 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:27.153450 15833 raft_consensus.cc:740] T 00000000000000000000000000000000 P f9d48da9888e4623b12185280dc0dcb8 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: f9d48da9888e4623b12185280dc0dcb8, State: Initialized, Role: FOLLOWER
I20260812 06:18:27.153995 15833 consensus_queue.cc:260] T 00000000000000000000000000000000 P f9d48da9888e4623b12185280dc0dcb8 [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: "f9d48da9888e4623b12185280dc0dcb8" member_type: VOTER }
I20260812 06:18:27.154131 15833 raft_consensus.cc:399] T 00000000000000000000000000000000 P f9d48da9888e4623b12185280dc0dcb8 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:27.154182 15833 raft_consensus.cc:493] T 00000000000000000000000000000000 P f9d48da9888e4623b12185280dc0dcb8 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:27.154269 15833 raft_consensus.cc:3060] T 00000000000000000000000000000000 P f9d48da9888e4623b12185280dc0dcb8 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:27.155005 15833 raft_consensus.cc:515] T 00000000000000000000000000000000 P f9d48da9888e4623b12185280dc0dcb8 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f9d48da9888e4623b12185280dc0dcb8" member_type: VOTER }
I20260812 06:18:27.155395 15833 leader_election.cc:304] T 00000000000000000000000000000000 P f9d48da9888e4623b12185280dc0dcb8 [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: f9d48da9888e4623b12185280dc0dcb8; no voters: 
I20260812 06:18:27.155689 15833 leader_election.cc:290] T 00000000000000000000000000000000 P f9d48da9888e4623b12185280dc0dcb8 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:27.155869 15836 raft_consensus.cc:2804] T 00000000000000000000000000000000 P f9d48da9888e4623b12185280dc0dcb8 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:27.156235 15836 raft_consensus.cc:697] T 00000000000000000000000000000000 P f9d48da9888e4623b12185280dc0dcb8 [term 1 LEADER]: Becoming Leader. State: Replica: f9d48da9888e4623b12185280dc0dcb8, State: Running, Role: LEADER
I20260812 06:18:27.156647 15836 consensus_queue.cc:237] T 00000000000000000000000000000000 P f9d48da9888e4623b12185280dc0dcb8 [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: "f9d48da9888e4623b12185280dc0dcb8" member_type: VOTER }
I20260812 06:18:27.156798 15833 sys_catalog.cc:565] T 00000000000000000000000000000000 P f9d48da9888e4623b12185280dc0dcb8 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:27.158636 15838 sys_catalog.cc:455] T 00000000000000000000000000000000 P f9d48da9888e4623b12185280dc0dcb8 [sys.catalog]: SysCatalogTable state changed. Reason: New leader f9d48da9888e4623b12185280dc0dcb8. Latest consensus state: current_term: 1 leader_uuid: "f9d48da9888e4623b12185280dc0dcb8" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f9d48da9888e4623b12185280dc0dcb8" member_type: VOTER } }
I20260812 06:18:27.158690 15837 sys_catalog.cc:455] T 00000000000000000000000000000000 P f9d48da9888e4623b12185280dc0dcb8 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "f9d48da9888e4623b12185280dc0dcb8" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f9d48da9888e4623b12185280dc0dcb8" member_type: VOTER } }
I20260812 06:18:27.158776 15838 sys_catalog.cc:458] T 00000000000000000000000000000000 P f9d48da9888e4623b12185280dc0dcb8 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:27.158790 15837 sys_catalog.cc:458] T 00000000000000000000000000000000 P f9d48da9888e4623b12185280dc0dcb8 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:27.159198 15851 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:27.159370 15750 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:27.161944 15851 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:27.166894 15851 catalog_manager.cc:1383] Generated new cluster ID: 5e493b38b9d94e7692395b6f38cd7471
I20260812 06:18:27.166965 15851 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:27.179566 15851 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:27.180615 15851 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:27.189073 15851 catalog_manager.cc:6092] T 00000000000000000000000000000000 P f9d48da9888e4623b12185280dc0dcb8: Generated new TSK 0
I20260812 06:18:27.189700 15851 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:27.192147 15750 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:27.194725 15858 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:18:27.194793 15861 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:18:27.194970 15859 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:18:27.195221 15750 server_base.cc:1061] running on GCE node
I20260812 06:18:27.195412 15750 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:27.195451 15750 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:18:27.195466 15750 hybrid_clock.cc:648] HybridClock initialized: now 1786515507195466 us; error 0 us; skew 500 ppm
I20260812 06:18:27.196420 15750 webserver.cc:533] Webserver started at http://127.15.97.129:37917/ using document root <none> and password file <none>
I20260812 06:18:27.196589 15750 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:27.196638 15750 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:27.196714 15750 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:27.197162 15750 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507080306-15750-0/minicluster-data/ts-0-root/instance:
uuid: "53dbaf1a532a4c9989a8616a21886305"
format_stamp: "Formatted at 2026-08-12 06:18:27 on dist-test-slave-27sr"
I20260812 06:18:27.198702 15750 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:27.199738 15867 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:18:27.200058 15750 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:27.200124 15750 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507080306-15750-0/minicluster-data/ts-0-root
uuid: "53dbaf1a532a4c9989a8616a21886305"
format_stamp: "Formatted at 2026-08-12 06:18:27 on dist-test-slave-27sr"
I20260812 06:18:27.200214 15750 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507080306-15750-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507080306-15750-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507080306-15750-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:18:27.223227 15750 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:27.223758 15750 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:27.224314 15750 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:27.225284 15750 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:27.225339 15750 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:27.225414 15750 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:27.225459 15750 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:27.232779 15750 rpc_server.cc:307] RPC server started. Bound to: 127.15.97.129:43417
I20260812 06:18:27.232805 15945 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.15.97.129:43417 every 8 connection(s)
I20260812 06:18:27.243458 15946 heartbeater.cc:344] Connected to a master server at 127.15.97.190:40907
I20260812 06:18:27.243742 15946 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:27.244225 15946 heartbeater.cc:507] Master 127.15.97.190:40907 requested a full tablet report, sending...
I20260812 06:18:27.245699 15790 ts_manager.cc:194] Registered new tserver with Master: 53dbaf1a532a4c9989a8616a21886305 (127.15.97.129:43417)
I20260812 06:18:27.245973 15750 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012457051s
I20260812 06:18:27.247030 15790 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:56554
I20260812 06:18:27.256387 15790 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:56570:
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:18:27.272274 15901 tablet_service.cc:1511] Processing CreateTablet for tablet d31ba9ed5401434c961725630087b6dc (DEFAULT_TABLE table=heavy-update-compaction-test [id=ccdcdcc49f724ecc85f8f3f85274af42]), partition=
I20260812 06:18:27.272756 15901 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet d31ba9ed5401434c961725630087b6dc. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:27.275292 15962 tablet_bootstrap.cc:492] T d31ba9ed5401434c961725630087b6dc P 53dbaf1a532a4c9989a8616a21886305: Bootstrap starting.
I20260812 06:18:27.276417 15962 tablet_bootstrap.cc:654] T d31ba9ed5401434c961725630087b6dc P 53dbaf1a532a4c9989a8616a21886305: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:27.277726 15962 tablet_bootstrap.cc:492] T d31ba9ed5401434c961725630087b6dc P 53dbaf1a532a4c9989a8616a21886305: No bootstrap required, opened a new log
I20260812 06:18:27.277828 15962 ts_tablet_manager.cc:1403] T d31ba9ed5401434c961725630087b6dc P 53dbaf1a532a4c9989a8616a21886305: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:18:27.278316 15962 raft_consensus.cc:359] T d31ba9ed5401434c961725630087b6dc P 53dbaf1a532a4c9989a8616a21886305 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "53dbaf1a532a4c9989a8616a21886305" member_type: VOTER last_known_addr { host: "127.15.97.129" port: 43417 } }
I20260812 06:18:27.278432 15962 raft_consensus.cc:385] T d31ba9ed5401434c961725630087b6dc P 53dbaf1a532a4c9989a8616a21886305 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:27.278463 15962 raft_consensus.cc:740] T d31ba9ed5401434c961725630087b6dc P 53dbaf1a532a4c9989a8616a21886305 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 53dbaf1a532a4c9989a8616a21886305, State: Initialized, Role: FOLLOWER
I20260812 06:18:27.278585 15962 consensus_queue.cc:260] T d31ba9ed5401434c961725630087b6dc P 53dbaf1a532a4c9989a8616a21886305 [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: "53dbaf1a532a4c9989a8616a21886305" member_type: VOTER last_known_addr { host: "127.15.97.129" port: 43417 } }
I20260812 06:18:27.278697 15962 raft_consensus.cc:399] T d31ba9ed5401434c961725630087b6dc P 53dbaf1a532a4c9989a8616a21886305 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:27.278739 15962 raft_consensus.cc:493] T d31ba9ed5401434c961725630087b6dc P 53dbaf1a532a4c9989a8616a21886305 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:27.278779 15962 raft_consensus.cc:3060] T d31ba9ed5401434c961725630087b6dc P 53dbaf1a532a4c9989a8616a21886305 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:27.279749 15962 raft_consensus.cc:515] T d31ba9ed5401434c961725630087b6dc P 53dbaf1a532a4c9989a8616a21886305 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "53dbaf1a532a4c9989a8616a21886305" member_type: VOTER last_known_addr { host: "127.15.97.129" port: 43417 } }
I20260812 06:18:27.279935 15962 leader_election.cc:304] T d31ba9ed5401434c961725630087b6dc P 53dbaf1a532a4c9989a8616a21886305 [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: 53dbaf1a532a4c9989a8616a21886305; no voters: 
I20260812 06:18:27.280148 15962 leader_election.cc:290] T d31ba9ed5401434c961725630087b6dc P 53dbaf1a532a4c9989a8616a21886305 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:27.280305 15964 raft_consensus.cc:2804] T d31ba9ed5401434c961725630087b6dc P 53dbaf1a532a4c9989a8616a21886305 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:27.280453 15962 ts_tablet_manager.cc:1434] T d31ba9ed5401434c961725630087b6dc P 53dbaf1a532a4c9989a8616a21886305: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:27.280853 15946 heartbeater.cc:499] Master 127.15.97.190:40907 was elected leader, sending a full tablet report...
I20260812 06:18:27.280586 15964 raft_consensus.cc:697] T d31ba9ed5401434c961725630087b6dc P 53dbaf1a532a4c9989a8616a21886305 [term 1 LEADER]: Becoming Leader. State: Replica: 53dbaf1a532a4c9989a8616a21886305, State: Running, Role: LEADER
I20260812 06:18:27.281322 15964 consensus_queue.cc:237] T d31ba9ed5401434c961725630087b6dc P 53dbaf1a532a4c9989a8616a21886305 [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: "53dbaf1a532a4c9989a8616a21886305" member_type: VOTER last_known_addr { host: "127.15.97.129" port: 43417 } }
I20260812 06:18:27.284498 15789 catalog_manager.cc:5719] T d31ba9ed5401434c961725630087b6dc P 53dbaf1a532a4c9989a8616a21886305 reported cstate change: term changed from 0 to 1, leader changed from <none> to 53dbaf1a532a4c9989a8616a21886305 (127.15.97.129). New cstate: current_term: 1 leader_uuid: "53dbaf1a532a4c9989a8616a21886305" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "53dbaf1a532a4c9989a8616a21886305" member_type: VOTER last_known_addr { host: "127.15.97.129" port: 43417 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:27.356175 15750 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.064s	user 0.028s	sys 0.003s
I20260812 06:18:27.484145 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling FlushMRSOp(d31ba9ed5401434c961725630087b6dc): perf score=15.086190
I20260812 06:18:27.656445 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: FlushMRSOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.172s	user 0.155s	sys 0.016s Metrics: {"bytes_written":14153574,"cfile_init":1,"compiler_manager_pool.queue_time_us":230,"delete_count":0,"dirs.queue_time_us":81,"dirs.run_cpu_time_us":335,"dirs.run_wall_time_us":1151,"drs_written":1,"lbm_read_time_us":76,"lbm_reads_lt_1ms":4,"lbm_write_time_us":43792,"lbm_writes_lt_1ms":712,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":151808,"thread_start_us":128,"threads_started":1,"update_count":1725}
I20260812 06:18:27.657691 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling UndoDeltaBlockGCOp(d31ba9ed5401434c961725630087b6dc): 12719213 bytes on disk
I20260812 06:18:27.658315 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: UndoDeltaBlockGCOp(d31ba9ed5401434c961725630087b6dc) 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:18:27.658784 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc): perf score=2.188937
I20260812 06:18:27.670706 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":3241138,"delete_count":0,"lbm_write_time_us":4348,"lbm_writes_lt_1ms":82,"reinsert_count":0,"update_count":395}
I20260812 06:18:27.671223 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling LogGCOp(d31ba9ed5401434c961725630087b6dc): free 20743880 bytes of WAL
I20260812 06:18:27.671548 15872 log_reader.cc:385] T d31ba9ed5401434c961725630087b6dc: removed 2 log segments from log reader
I20260812 06:18:27.671624 15872 log.cc:1079] T d31ba9ed5401434c961725630087b6dc P 53dbaf1a532a4c9989a8616a21886305: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/d31ba9ed5401434c961725630087b6dc/wal-000000001 (ops 1-6)
I20260812 06:18:27.671701 15872 log.cc:1079] T d31ba9ed5401434c961725630087b6dc P 53dbaf1a532a4c9989a8616a21886305: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/d31ba9ed5401434c961725630087b6dc/wal-000000002 (ops 7-11)
I20260812 06:18:27.677284 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: LogGCOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.006s	user 0.000s	sys 0.005s Metrics: {}
I20260812 06:18:27.677742 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc): perf score=1.196750
I20260812 06:18:27.688555 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.011s	user 0.001s	sys 0.009s Metrics: {"bytes_written":2707805,"delete_count":0,"lbm_write_time_us":3939,"lbm_writes_lt_1ms":69,"reinsert_count":0,"update_count":330}
I20260812 06:18:27.689148 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling MajorDeltaCompactionOp(d31ba9ed5401434c961725630087b6dc): perf score=1.000000
I20260812 06:18:27.893867 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: MajorDeltaCompactionOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.205s	user 0.152s	sys 0.040s Metrics: {"cfile_cache_miss":523,"cfile_cache_miss_bytes":24364517,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":912,"lbm_read_time_us":12842,"lbm_reads_lt_1ms":559,"lbm_write_time_us":33780,"lbm_writes_lt_1ms":533,"peak_mem_usage":61665166,"reinsert_count":0,"spinlock_wait_cycles":6400,"thread_start_us":369,"threads_started":5,"update_count":2450}
I20260812 06:18:27.894527 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc): perf score=14.095187
I20260812 06:18:27.946352 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.052s	user 0.030s	sys 0.013s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19808,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:27.946838 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc): perf score=2.188937
I20260812 06:18:27.958974 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4087,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:27.959548 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling MajorDeltaCompactionOp(d31ba9ed5401434c961725630087b6dc): perf score=1.000000
I20260812 06:18:28.116129 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: MajorDeltaCompactionOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.156s	user 0.108s	sys 0.043s 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":848,"lbm_read_time_us":9982,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32383,"lbm_writes_lt_1ms":543,"mutex_wait_us":300,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10368,"update_count":2500}
I20260812 06:18:28.116868 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc): perf score=11.118625
I20260812 06:18:28.147615 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.031s	user 0.020s	sys 0.008s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":13645,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:28.148373 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc): perf score=2.188937
I20260812 06:18:28.165414 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.017s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":7245,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":92,"reinsert_count":0,"update_count":450}
I20260812 06:18:28.165876 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling MajorDeltaCompactionOp(d31ba9ed5401434c961725630087b6dc): perf score=1.000000
I20260812 06:18:28.295284 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: MajorDeltaCompactionOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.129s	user 0.097s	sys 0.029s 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":63,"lbm_read_time_us":7399,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26806,"lbm_writes_lt_1ms":443,"mutex_wait_us":2,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:18:28.295979 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc): perf score=10.126437
I20260812 06:18:28.340667 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.044s	user 0.015s	sys 0.028s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":22600,"lbm_writes_1-10_ms":4,"lbm_writes_lt_1ms":299,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":1500}
I20260812 06:18:28.341212 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc): perf score=2.188937
I20260812 06:18:28.356865 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.015s	user 0.012s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5257,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:28.357331 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling MajorDeltaCompactionOp(d31ba9ed5401434c961725630087b6dc): perf score=1.000000
I20260812 06:18:28.496843 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: MajorDeltaCompactionOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.139s	user 0.090s	sys 0.049s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672280,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":614,"lbm_read_time_us":9909,"lbm_reads_lt_1ms":468,"lbm_write_time_us":27313,"lbm_writes_lt_1ms":443,"mutex_wait_us":285,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":16512,"update_count":2000}
I20260812 06:18:28.497599 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc): perf score=10.126437
I20260812 06:18:28.539465 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.042s	user 0.023s	sys 0.015s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":13538,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:28.540146 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc): perf score=2.188937
I20260812 06:18:28.551179 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4277,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:28.551765 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling MajorDeltaCompactionOp(d31ba9ed5401434c961725630087b6dc): perf score=1.000000
I20260812 06:18:28.708400 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: MajorDeltaCompactionOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.156s	user 0.102s	sys 0.051s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":355,"lbm_read_time_us":11763,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23987,"lbm_writes_lt_1ms":443,"mutex_wait_us":57,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2048,"update_count":2000}
I20260812 06:18:28.709107 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc): perf score=10.126437
I20260812 06:18:28.755693 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.046s	user 0.025s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18251,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:18:28.756219 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc): perf score=2.188937
I20260812 06:18:28.767462 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4188,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:28.768186 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling MajorDeltaCompactionOp(d31ba9ed5401434c961725630087b6dc): perf score=1.000000
I20260812 06:18:28.889307 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: MajorDeltaCompactionOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.121s	user 0.108s	sys 0.013s 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":156,"lbm_read_time_us":9158,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23079,"lbm_writes_lt_1ms":443,"mutex_wait_us":22,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10112,"update_count":2000}
I20260812 06:18:28.890080 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc): perf score=10.126437
I20260812 06:18:28.931166 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.041s	user 0.018s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18641,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":300,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":1500}
I20260812 06:18:28.931951 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc): perf score=2.188937
I20260812 06:18:28.948148 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.016s	user 0.015s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6378,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:28.948671 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling FlushMRSOp(d31ba9ed5401434c961725630087b6dc): perf score=1.000000
I20260812 06:18:28.978049 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: FlushMRSOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.029s	user 0.027s	sys 0.000s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":92,"dirs.run_cpu_time_us":286,"dirs.run_wall_time_us":1534,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1590,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:28.978953 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling LogGCOp(d31ba9ed5401434c961725630087b6dc): free 120553396 bytes of WAL
I20260812 06:18:28.979225 15872 log_reader.cc:385] T d31ba9ed5401434c961725630087b6dc: removed 12 log segments from log reader
I20260812 06:18:28.979277 15872 log.cc:1079] T d31ba9ed5401434c961725630087b6dc P 53dbaf1a532a4c9989a8616a21886305: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/d31ba9ed5401434c961725630087b6dc/wal-000000003 (ops 12-16)
I20260812 06:18:28.979310 15872 log.cc:1079] T d31ba9ed5401434c961725630087b6dc P 53dbaf1a532a4c9989a8616a21886305: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/d31ba9ed5401434c961725630087b6dc/wal-000000004 (ops 17-20)
I20260812 06:18:28.979355 15872 log.cc:1079] T d31ba9ed5401434c961725630087b6dc P 53dbaf1a532a4c9989a8616a21886305: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/d31ba9ed5401434c961725630087b6dc/wal-000000005 (ops 21-25)
I20260812 06:18:28.979405 15872 log.cc:1079] T d31ba9ed5401434c961725630087b6dc P 53dbaf1a532a4c9989a8616a21886305: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/d31ba9ed5401434c961725630087b6dc/wal-000000006 (ops 26-30)
I20260812 06:18:28.979425 15872 log.cc:1079] T d31ba9ed5401434c961725630087b6dc P 53dbaf1a532a4c9989a8616a21886305: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/d31ba9ed5401434c961725630087b6dc/wal-000000007 (ops 31-35)
I20260812 06:18:28.979481 15872 log.cc:1079] T d31ba9ed5401434c961725630087b6dc P 53dbaf1a532a4c9989a8616a21886305: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/d31ba9ed5401434c961725630087b6dc/wal-000000008 (ops 36-40)
I20260812 06:18:28.979525 15872 log.cc:1079] T d31ba9ed5401434c961725630087b6dc P 53dbaf1a532a4c9989a8616a21886305: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/d31ba9ed5401434c961725630087b6dc/wal-000000009 (ops 41-45)
I20260812 06:18:28.979565 15872 log.cc:1079] T d31ba9ed5401434c961725630087b6dc P 53dbaf1a532a4c9989a8616a21886305: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/d31ba9ed5401434c961725630087b6dc/wal-000000010 (ops 46-50)
I20260812 06:18:28.979609 15872 log.cc:1079] T d31ba9ed5401434c961725630087b6dc P 53dbaf1a532a4c9989a8616a21886305: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/d31ba9ed5401434c961725630087b6dc/wal-000000011 (ops 51-54)
I20260812 06:18:28.979648 15872 log.cc:1079] T d31ba9ed5401434c961725630087b6dc P 53dbaf1a532a4c9989a8616a21886305: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/d31ba9ed5401434c961725630087b6dc/wal-000000012 (ops 55-59)
I20260812 06:18:28.979686 15872 log.cc:1079] T d31ba9ed5401434c961725630087b6dc P 53dbaf1a532a4c9989a8616a21886305: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/d31ba9ed5401434c961725630087b6dc/wal-000000013 (ops 60-64)
I20260812 06:18:28.979722 15872 log.cc:1079] T d31ba9ed5401434c961725630087b6dc P 53dbaf1a532a4c9989a8616a21886305: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/d31ba9ed5401434c961725630087b6dc/wal-000000014 (ops 65-69)
I20260812 06:18:29.007586 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: LogGCOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.028s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:18:29.008107 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling UndoDeltaBlockGCOp(d31ba9ed5401434c961725630087b6dc): 472 bytes on disk
I20260812 06:18:29.008622 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: UndoDeltaBlockGCOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4}
I20260812 06:18:29.009155 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc): perf score=6.157687
I20260812 06:18:29.030195 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.021s	user 0.006s	sys 0.013s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":8924,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:18:29.030655 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling MajorDeltaCompactionOp(d31ba9ed5401434c961725630087b6dc): perf score=1.000000
I20260812 06:18:29.196190 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: MajorDeltaCompactionOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.165s	user 0.125s	sys 0.040s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877221,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":776,"lbm_read_time_us":12053,"lbm_reads_lt_1ms":669,"lbm_write_time_us":32135,"lbm_writes_lt_1ms":643,"mutex_wait_us":71,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1792,"thread_start_us":89,"threads_started":1,"update_count":3000}
I20260812 06:18:29.197994 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc): perf score=14.095187
I20260812 06:18:29.249379 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.051s	user 0.030s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22673,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:29.249917 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc): perf score=2.188937
I20260812 06:18:29.263195 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.013s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4775,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:29.263769 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling MajorDeltaCompactionOp(d31ba9ed5401434c961725630087b6dc): perf score=1.000000
I20260812 06:18:29.429148 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: MajorDeltaCompactionOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.165s	user 0.127s	sys 0.032s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":801,"lbm_read_time_us":11742,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28872,"lbm_writes_lt_1ms":543,"mutex_wait_us":395,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2500}
I20260812 06:18:29.429993 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc): perf score=14.095187
I20260812 06:18:29.480333 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.050s	user 0.019s	sys 0.028s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":21137,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:29.480872 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling MajorDeltaCompactionOp(d31ba9ed5401434c961725630087b6dc): perf score=1.000000
I20260812 06:18:29.633313 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: MajorDeltaCompactionOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.152s	user 0.111s	sys 0.040s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672156,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":860,"lbm_read_time_us":10866,"lbm_reads_lt_1ms":463,"lbm_write_time_us":25075,"lbm_writes_lt_1ms":443,"mutex_wait_us":293,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7296,"update_count":2000}
I20260812 06:18:29.634054 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc): perf score=11.118625
I20260812 06:18:29.672899 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.039s	user 0.038s	sys 0.000s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":16386,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:29.673669 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc): perf score=2.188937
I20260812 06:18:29.688449 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.015s	user 0.006s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5524,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:29.688968 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling MajorDeltaCompactionOp(d31ba9ed5401434c961725630087b6dc): perf score=1.000000
I20260812 06:18:29.805929 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: MajorDeltaCompactionOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.117s	user 0.088s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672269,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":808,"lbm_read_time_us":7949,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23619,"lbm_writes_lt_1ms":443,"mutex_wait_us":330,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7424,"update_count":2000}
I20260812 06:18:29.806694 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc): perf score=10.126437
I20260812 06:18:29.844931 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.038s	user 0.031s	sys 0.000s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":13798,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:29.845500 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc): perf score=2.188937
I20260812 06:18:29.860626 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.015s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5865,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:29.861281 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling MajorDeltaCompactionOp(d31ba9ed5401434c961725630087b6dc): perf score=1.000000
I20260812 06:18:29.985420 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: MajorDeltaCompactionOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.124s	user 0.089s	sys 0.034s 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":310,"lbm_read_time_us":8072,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24489,"lbm_writes_lt_1ms":443,"mutex_wait_us":62,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:18:29.986184 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc): perf score=10.126437
I20260812 06:18:30.030525 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.044s	user 0.023s	sys 0.017s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18768,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:30.031143 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc): perf score=2.188937
I20260812 06:18:30.043675 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4474,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:30.044276 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling MajorDeltaCompactionOp(d31ba9ed5401434c961725630087b6dc): perf score=1.000000
I20260812 06:18:30.182261 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: MajorDeltaCompactionOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.138s	user 0.111s	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":352,"lbm_read_time_us":12106,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26373,"lbm_writes_lt_1ms":443,"mutex_wait_us":74,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":32128,"update_count":2000}
I20260812 06:18:30.182971 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc): perf score=10.126437
I20260812 06:18:30.234336 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.051s	user 0.015s	sys 0.029s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15108,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:30.234962 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc): perf score=2.188937
I20260812 06:18:30.252379 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.017s	user 0.009s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6607,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:30.252977 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling MajorDeltaCompactionOp(d31ba9ed5401434c961725630087b6dc): perf score=1.000000
I20260812 06:18:30.411639 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: MajorDeltaCompactionOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.158s	user 0.102s	sys 0.053s 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":293,"lbm_read_time_us":12934,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26514,"lbm_writes_lt_1ms":443,"mutex_wait_us":50,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":27776,"update_count":2000}
I20260812 06:18:30.412443 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc): perf score=10.126437
I20260812 06:18:30.467000 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.054s	user 0.026s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20184,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:30.467602 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc): perf score=2.188937
I20260812 06:18:30.479826 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4350,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:30.480436 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling FlushMRSOp(d31ba9ed5401434c961725630087b6dc): perf score=1.000000
I20260812 06:18:30.513613 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: FlushMRSOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.033s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":70,"dirs.run_cpu_time_us":280,"dirs.run_wall_time_us":1514,"drs_written":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1972,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:30.514573 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling LogGCOp(d31ba9ed5401434c961725630087b6dc): free 124257248 bytes of WAL
I20260812 06:18:30.514859 15872 log_reader.cc:385] T d31ba9ed5401434c961725630087b6dc: removed 12 log segments from log reader
I20260812 06:18:30.514912 15872 log.cc:1079] T d31ba9ed5401434c961725630087b6dc P 53dbaf1a532a4c9989a8616a21886305: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/d31ba9ed5401434c961725630087b6dc/wal-000000015 (ops 70-74)
I20260812 06:18:30.514967 15872 log.cc:1079] T d31ba9ed5401434c961725630087b6dc P 53dbaf1a532a4c9989a8616a21886305: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/d31ba9ed5401434c961725630087b6dc/wal-000000016 (ops 75-79)
I20260812 06:18:30.514992 15872 log.cc:1079] T d31ba9ed5401434c961725630087b6dc P 53dbaf1a532a4c9989a8616a21886305: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/d31ba9ed5401434c961725630087b6dc/wal-000000017 (ops 80-84)
I20260812 06:18:30.515021 15872 log.cc:1079] T d31ba9ed5401434c961725630087b6dc P 53dbaf1a532a4c9989a8616a21886305: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/d31ba9ed5401434c961725630087b6dc/wal-000000018 (ops 85-89)
I20260812 06:18:30.515050 15872 log.cc:1079] T d31ba9ed5401434c961725630087b6dc P 53dbaf1a532a4c9989a8616a21886305: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/d31ba9ed5401434c961725630087b6dc/wal-000000019 (ops 90-94)
I20260812 06:18:30.515085 15872 log.cc:1079] T d31ba9ed5401434c961725630087b6dc P 53dbaf1a532a4c9989a8616a21886305: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/d31ba9ed5401434c961725630087b6dc/wal-000000020 (ops 95-99)
I20260812 06:18:30.515115 15872 log.cc:1079] T d31ba9ed5401434c961725630087b6dc P 53dbaf1a532a4c9989a8616a21886305: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/d31ba9ed5401434c961725630087b6dc/wal-000000021 (ops 100-104)
I20260812 06:18:30.515141 15872 log.cc:1079] T d31ba9ed5401434c961725630087b6dc P 53dbaf1a532a4c9989a8616a21886305: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/d31ba9ed5401434c961725630087b6dc/wal-000000022 (ops 105-109)
I20260812 06:18:30.515169 15872 log.cc:1079] T d31ba9ed5401434c961725630087b6dc P 53dbaf1a532a4c9989a8616a21886305: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/d31ba9ed5401434c961725630087b6dc/wal-000000023 (ops 110-114)
I20260812 06:18:30.515196 15872 log.cc:1079] T d31ba9ed5401434c961725630087b6dc P 53dbaf1a532a4c9989a8616a21886305: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/d31ba9ed5401434c961725630087b6dc/wal-000000024 (ops 115-118)
I20260812 06:18:30.515231 15872 log.cc:1079] T d31ba9ed5401434c961725630087b6dc P 53dbaf1a532a4c9989a8616a21886305: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/d31ba9ed5401434c961725630087b6dc/wal-000000025 (ops 119-123)
I20260812 06:18:30.515264 15872 log.cc:1079] T d31ba9ed5401434c961725630087b6dc P 53dbaf1a532a4c9989a8616a21886305: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/d31ba9ed5401434c961725630087b6dc/wal-000000026 (ops 124-128)
I20260812 06:18:30.548384 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: LogGCOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.034s	user 0.000s	sys 0.033s Metrics: {}
I20260812 06:18:30.549052 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc): perf score=3.181125
I20260812 06:18:30.570981 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.022s	user 0.005s	sys 0.013s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":4532,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:30.571544 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling UndoDeltaBlockGCOp(d31ba9ed5401434c961725630087b6dc): 473 bytes on disk
I20260812 06:18:30.572108 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: UndoDeltaBlockGCOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":111,"lbm_reads_lt_1ms":4}
I20260812 06:18:30.572631 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc): perf score=2.188937
I20260812 06:18:30.583455 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4015,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:30.584163 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling MajorDeltaCompactionOp(d31ba9ed5401434c961725630087b6dc): perf score=1.000000
I20260812 06:18:30.802309 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: MajorDeltaCompactionOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.218s	user 0.120s	sys 0.085s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877328,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":2171,"lbm_read_time_us":15504,"lbm_reads_lt_1ms":674,"lbm_write_time_us":34359,"lbm_writes_lt_1ms":643,"mutex_wait_us":920,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3840,"thread_start_us":83,"threads_started":1,"update_count":3000}
I20260812 06:18:30.803337 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc): perf score=14.095187
I20260812 06:18:30.864557 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.061s	user 0.028s	sys 0.028s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19672,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:30.865197 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc): perf score=2.188937
I20260812 06:18:30.876199 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4177,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:30.876677 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling MajorDeltaCompactionOp(d31ba9ed5401434c961725630087b6dc): perf score=1.000000
I20260812 06:18:31.059486 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: MajorDeltaCompactionOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.183s	user 0.137s	sys 0.045s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":806,"lbm_read_time_us":13195,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32772,"lbm_writes_lt_1ms":543,"mutex_wait_us":344,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9088,"update_count":2500}
I20260812 06:18:31.060111 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc): perf score=10.126437
I20260812 06:18:31.101118 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.041s	user 0.035s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17809,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:31.101732 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc): perf score=2.188937
I20260812 06:18:31.116267 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.014s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5207,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:31.116753 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling MajorDeltaCompactionOp(d31ba9ed5401434c961725630087b6dc): perf score=1.000000
I20260812 06:18:31.267992 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: MajorDeltaCompactionOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.151s	user 0.120s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":743,"lbm_read_time_us":11232,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27625,"lbm_writes_lt_1ms":443,"mutex_wait_us":51,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11648,"update_count":2000}
I20260812 06:18:31.268622 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc): perf score=11.118625
I20260812 06:18:31.305737 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.037s	user 0.033s	sys 0.004s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15853,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:31.306283 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc): perf score=2.188937
I20260812 06:18:31.332664 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.026s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5109,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:31.333175 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc): perf score=2.188937
I20260812 06:18:31.349259 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.016s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102660,"delete_count":0,"lbm_write_time_us":6257,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:31.350162 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling MajorDeltaCompactionOp(d31ba9ed5401434c961725630087b6dc): perf score=1.000000
I20260812 06:18:31.506335 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: MajorDeltaCompactionOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.155s	user 0.112s	sys 0.038s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774800,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":247,"lbm_read_time_us":12871,"lbm_reads_lt_1ms":573,"lbm_write_time_us":27956,"lbm_writes_lt_1ms":543,"mutex_wait_us":93,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12544,"update_count":2500}
I20260812 06:18:31.507108 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc): perf score=14.095187
I20260812 06:18:31.562315 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.055s	user 0.025s	sys 0.025s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":23791,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:31.562881 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc): perf score=2.188937
I20260812 06:18:31.574594 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.012s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4255,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:31.575093 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling MajorDeltaCompactionOp(d31ba9ed5401434c961725630087b6dc): perf score=1.000000
I20260812 06:18:31.736307 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: MajorDeltaCompactionOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.161s	user 0.134s	sys 0.027s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":460,"lbm_read_time_us":12357,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31260,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12800,"update_count":2500}
I20260812 06:18:31.737128 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc): perf score=11.118625
I20260812 06:18:31.774992 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.038s	user 0.021s	sys 0.014s Metrics: {"bytes_written":13045918,"delete_count":0,"lbm_write_time_us":16019,"lbm_writes_lt_1ms":321,"reinsert_count":0,"update_count":1590}
I20260812 06:18:31.775626 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc): perf score=2.188937
I20260812 06:18:31.793622 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.018s	user 0.010s	sys 0.003s Metrics: {"bytes_written":3364205,"delete_count":0,"lbm_write_time_us":5697,"lbm_writes_lt_1ms":85,"reinsert_count":0,"update_count":410}
I20260812 06:18:31.794255 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling MajorDeltaCompactionOp(d31ba9ed5401434c961725630087b6dc): perf score=1.000000
I20260812 06:18:31.939970 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: MajorDeltaCompactionOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.145s	user 0.098s	sys 0.047s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672251,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":146,"lbm_read_time_us":10996,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25758,"lbm_writes_lt_1ms":443,"mutex_wait_us":1,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:18:31.940763 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc): perf score=10.126437
I20260812 06:18:31.986604 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.046s	user 0.023s	sys 0.020s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":20341,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:31.987303 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc): perf score=2.188937
I20260812 06:18:32.010823 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.023s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5204,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:32.011372 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc): perf score=2.188937
I20260812 06:18:32.032514 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.021s	user 0.006s	sys 0.014s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4336,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:32.033067 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling FlushMRSOp(d31ba9ed5401434c961725630087b6dc): perf score=1.000000
I20260812 06:18:32.073890 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: FlushMRSOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.041s	user 0.033s	sys 0.000s Metrics: {"bytes_written":1234477,"cfile_init":1,"dirs.queue_time_us":121,"dirs.run_cpu_time_us":203,"dirs.run_wall_time_us":1490,"drs_written":1,"lbm_read_time_us":69,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2126,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:32.074606 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling LogGCOp(d31ba9ed5401434c961725630087b6dc): free 121006700 bytes of WAL
I20260812 06:18:32.074864 15872 log_reader.cc:385] T d31ba9ed5401434c961725630087b6dc: removed 12 log segments from log reader
I20260812 06:18:32.074913 15872 log.cc:1079] T d31ba9ed5401434c961725630087b6dc P 53dbaf1a532a4c9989a8616a21886305: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/d31ba9ed5401434c961725630087b6dc/wal-000000027 (ops 129-133)
I20260812 06:18:32.074941 15872 log.cc:1079] T d31ba9ed5401434c961725630087b6dc P 53dbaf1a532a4c9989a8616a21886305: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/d31ba9ed5401434c961725630087b6dc/wal-000000028 (ops 134-138)
I20260812 06:18:32.075021 15872 log.cc:1079] T d31ba9ed5401434c961725630087b6dc P 53dbaf1a532a4c9989a8616a21886305: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/d31ba9ed5401434c961725630087b6dc/wal-000000029 (ops 139-143)
I20260812 06:18:32.075054 15872 log.cc:1079] T d31ba9ed5401434c961725630087b6dc P 53dbaf1a532a4c9989a8616a21886305: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/d31ba9ed5401434c961725630087b6dc/wal-000000030 (ops 144-148)
I20260812 06:18:32.075099 15872 log.cc:1079] T d31ba9ed5401434c961725630087b6dc P 53dbaf1a532a4c9989a8616a21886305: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/d31ba9ed5401434c961725630087b6dc/wal-000000031 (ops 149-153)
I20260812 06:18:32.075160 15872 log.cc:1079] T d31ba9ed5401434c961725630087b6dc P 53dbaf1a532a4c9989a8616a21886305: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/d31ba9ed5401434c961725630087b6dc/wal-000000032 (ops 154-158)
I20260812 06:18:32.075204 15872 log.cc:1079] T d31ba9ed5401434c961725630087b6dc P 53dbaf1a532a4c9989a8616a21886305: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/d31ba9ed5401434c961725630087b6dc/wal-000000033 (ops 159-162)
I20260812 06:18:32.075244 15872 log.cc:1079] T d31ba9ed5401434c961725630087b6dc P 53dbaf1a532a4c9989a8616a21886305: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/d31ba9ed5401434c961725630087b6dc/wal-000000034 (ops 163-167)
I20260812 06:18:32.075284 15872 log.cc:1079] T d31ba9ed5401434c961725630087b6dc P 53dbaf1a532a4c9989a8616a21886305: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/d31ba9ed5401434c961725630087b6dc/wal-000000035 (ops 168-172)
I20260812 06:18:32.075323 15872 log.cc:1079] T d31ba9ed5401434c961725630087b6dc P 53dbaf1a532a4c9989a8616a21886305: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/d31ba9ed5401434c961725630087b6dc/wal-000000036 (ops 173-177)
I20260812 06:18:32.075362 15872 log.cc:1079] T d31ba9ed5401434c961725630087b6dc P 53dbaf1a532a4c9989a8616a21886305: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/d31ba9ed5401434c961725630087b6dc/wal-000000037 (ops 178-182)
I20260812 06:18:32.075402 15872 log.cc:1079] T d31ba9ed5401434c961725630087b6dc P 53dbaf1a532a4c9989a8616a21886305: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/d31ba9ed5401434c961725630087b6dc/wal-000000038 (ops 183-187)
I20260812 06:18:32.106382 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: LogGCOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.032s	user 0.002s	sys 0.027s Metrics: {}
I20260812 06:18:32.106817 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling UndoDeltaBlockGCOp(d31ba9ed5401434c961725630087b6dc): 472 bytes on disk
I20260812 06:18:32.107617 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: UndoDeltaBlockGCOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4}
I20260812 06:18:32.108322 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc): perf score=3.181125
I20260812 06:18:32.126938 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.018s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4465,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:32.127398 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc): perf score=2.188937
I20260812 06:18:32.137019 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3482,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:32.137445 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling MajorDeltaCompactionOp(d31ba9ed5401434c961725630087b6dc): perf score=1.000000
I20260812 06:18:32.331709 15750 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.975s	user 1.779s	sys 0.167s
I20260812 06:18:32.361944 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: MajorDeltaCompactionOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.224s	user 0.152s	sys 0.070s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979858,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"lbm_read_time_us":15744,"lbm_reads_lt_1ms":771,"lbm_write_time_us":40097,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":3500}
I20260812 06:18:32.362527 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc): perf score=14.095187
I20260812 06:18:32.395466 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: FlushDeltaMemStoresOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.033s	user 0.020s	sys 0.012s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":15994,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:32.396055 15948 maintenance_manager.cc:419] P 53dbaf1a532a4c9989a8616a21886305: Scheduling MajorDeltaCompactionOp(d31ba9ed5401434c961725630087b6dc): perf score=1.000000
I20260812 06:18:32.453984 15750 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.122s	user 0.002s	sys 0.000s
I20260812 06:18:32.454684 15750 tablet_server.cc:179] TabletServer@127.15.97.129:0 shutting down...
I20260812 06:18:32.519326 15872 maintenance_manager.cc:643] P 53dbaf1a532a4c9989a8616a21886305: MajorDeltaCompactionOp(d31ba9ed5401434c961725630087b6dc) complete. Timing: real 0.123s	user 0.078s	sys 0.045s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672156,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":314,"lbm_read_time_us":9614,"lbm_reads_lt_1ms":467,"lbm_write_time_us":25362,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":50,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":162176,"update_count":2000}
I20260812 06:18:32.520205 15750 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:32.520769 15750 tablet_replica.cc:333] T d31ba9ed5401434c961725630087b6dc P 53dbaf1a532a4c9989a8616a21886305: stopping tablet replica
I20260812 06:18:32.521023 15750 raft_consensus.cc:2243] T d31ba9ed5401434c961725630087b6dc P 53dbaf1a532a4c9989a8616a21886305 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:32.521274 15750 raft_consensus.cc:2272] T d31ba9ed5401434c961725630087b6dc P 53dbaf1a532a4c9989a8616a21886305 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:32.537710 15750 tablet_server.cc:196] TabletServer@127.15.97.129:0 shutdown complete.
I20260812 06:18:32.573290 15750 master.cc:562] Master@127.15.97.190:40907 shutting down...
I20260812 06:18:32.577235 15750 raft_consensus.cc:2243] T 00000000000000000000000000000000 P f9d48da9888e4623b12185280dc0dcb8 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:32.577447 15750 raft_consensus.cc:2272] T 00000000000000000000000000000000 P f9d48da9888e4623b12185280dc0dcb8 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:32.577541 15750 tablet_replica.cc:333] T 00000000000000000000000000000000 P f9d48da9888e4623b12185280dc0dcb8: stopping tablet replica
I20260812 06:18:32.590109 15750 master.cc:584] Master@127.15.97.190:40907 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5603 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:32.710527 15750 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.15.97.190:33475
I20260812 06:18:32.710932 15750 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:32.713595 15988 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:18:32.713631 15985 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:18:32.713835 15986 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:18:32.713971 15750 server_base.cc:1061] running on GCE node
I20260812 06:18:32.714133 15750 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:32.714171 15750 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:18:32.714188 15750 hybrid_clock.cc:648] HybridClock initialized: now 1786515512714188 us; error 0 us; skew 500 ppm
I20260812 06:18:32.715060 15750 webserver.cc:533] Webserver started at http://127.15.97.190:34491/ using document root <none> and password file <none>
I20260812 06:18:32.715276 15750 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:32.715334 15750 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:32.715394 15750 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:32.715776 15750 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507080306-15750-0/minicluster-data/master-0-root/instance:
uuid: "b38ae8318f0c4332a653f973fc7df66a"
format_stamp: "Formatted at 2026-08-12 06:18:32 on dist-test-slave-27sr"
I20260812 06:18:32.717921 15750 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.000s	sys 0.001s
I20260812 06:18:32.718906 15995 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:18:32.719215 15750 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:32.719292 15750 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507080306-15750-0/minicluster-data/master-0-root
uuid: "b38ae8318f0c4332a653f973fc7df66a"
format_stamp: "Formatted at 2026-08-12 06:18:32 on dist-test-slave-27sr"
I20260812 06:18:32.719347 15750 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507080306-15750-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507080306-15750-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507080306-15750-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:18:32.732753 15750 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:32.733119 15750 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:32.737145 15750 rpc_server.cc:307] RPC server started. Bound to: 127.15.97.190:33475
I20260812 06:18:32.737174 16053 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.15.97.190:33475 every 8 connection(s)
I20260812 06:18:32.738090 16054 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:18:32.740016 16054 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P b38ae8318f0c4332a653f973fc7df66a: Bootstrap starting.
I20260812 06:18:32.740823 16054 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P b38ae8318f0c4332a653f973fc7df66a: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:32.741896 16054 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P b38ae8318f0c4332a653f973fc7df66a: No bootstrap required, opened a new log
I20260812 06:18:32.742348 16054 raft_consensus.cc:359] T 00000000000000000000000000000000 P b38ae8318f0c4332a653f973fc7df66a [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b38ae8318f0c4332a653f973fc7df66a" member_type: VOTER }
I20260812 06:18:32.742436 16054 raft_consensus.cc:385] T 00000000000000000000000000000000 P b38ae8318f0c4332a653f973fc7df66a [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:32.742492 16054 raft_consensus.cc:740] T 00000000000000000000000000000000 P b38ae8318f0c4332a653f973fc7df66a [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: b38ae8318f0c4332a653f973fc7df66a, State: Initialized, Role: FOLLOWER
I20260812 06:18:32.742681 16054 consensus_queue.cc:260] T 00000000000000000000000000000000 P b38ae8318f0c4332a653f973fc7df66a [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: "b38ae8318f0c4332a653f973fc7df66a" member_type: VOTER }
I20260812 06:18:32.742756 16054 raft_consensus.cc:399] T 00000000000000000000000000000000 P b38ae8318f0c4332a653f973fc7df66a [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:32.742811 16054 raft_consensus.cc:493] T 00000000000000000000000000000000 P b38ae8318f0c4332a653f973fc7df66a [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:32.742875 16054 raft_consensus.cc:3060] T 00000000000000000000000000000000 P b38ae8318f0c4332a653f973fc7df66a [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:32.743567 16054 raft_consensus.cc:515] T 00000000000000000000000000000000 P b38ae8318f0c4332a653f973fc7df66a [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b38ae8318f0c4332a653f973fc7df66a" member_type: VOTER }
I20260812 06:18:32.743713 16054 leader_election.cc:304] T 00000000000000000000000000000000 P b38ae8318f0c4332a653f973fc7df66a [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: b38ae8318f0c4332a653f973fc7df66a; no voters: 
I20260812 06:18:32.743968 16054 leader_election.cc:290] T 00000000000000000000000000000000 P b38ae8318f0c4332a653f973fc7df66a [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:32.744042 16057 raft_consensus.cc:2804] T 00000000000000000000000000000000 P b38ae8318f0c4332a653f973fc7df66a [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:32.744330 16057 raft_consensus.cc:697] T 00000000000000000000000000000000 P b38ae8318f0c4332a653f973fc7df66a [term 1 LEADER]: Becoming Leader. State: Replica: b38ae8318f0c4332a653f973fc7df66a, State: Running, Role: LEADER
I20260812 06:18:32.744442 16054 sys_catalog.cc:565] T 00000000000000000000000000000000 P b38ae8318f0c4332a653f973fc7df66a [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:32.744468 16057 consensus_queue.cc:237] T 00000000000000000000000000000000 P b38ae8318f0c4332a653f973fc7df66a [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: "b38ae8318f0c4332a653f973fc7df66a" member_type: VOTER }
I20260812 06:18:32.744930 16062 sys_catalog.cc:455] T 00000000000000000000000000000000 P b38ae8318f0c4332a653f973fc7df66a [sys.catalog]: SysCatalogTable state changed. Reason: New leader b38ae8318f0c4332a653f973fc7df66a. Latest consensus state: current_term: 1 leader_uuid: "b38ae8318f0c4332a653f973fc7df66a" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b38ae8318f0c4332a653f973fc7df66a" member_type: VOTER } }
I20260812 06:18:32.745057 16062 sys_catalog.cc:458] T 00000000000000000000000000000000 P b38ae8318f0c4332a653f973fc7df66a [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:32.744916 16058 sys_catalog.cc:455] T 00000000000000000000000000000000 P b38ae8318f0c4332a653f973fc7df66a [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "b38ae8318f0c4332a653f973fc7df66a" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b38ae8318f0c4332a653f973fc7df66a" member_type: VOTER } }
I20260812 06:18:32.745353 16058 sys_catalog.cc:458] T 00000000000000000000000000000000 P b38ae8318f0c4332a653f973fc7df66a [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:32.746291 15750 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:18:32.746877 16081 catalog_manager.cc:1594] T 00000000000000000000000000000000 P b38ae8318f0c4332a653f973fc7df66a: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:18:32.746935 16081 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:18:32.747011 16068 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:32.747673 16068 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:32.749485 16068 catalog_manager.cc:1383] Generated new cluster ID: fbd1e76bfc704ebd840397df82c0c8a1
I20260812 06:18:32.749547 16068 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:32.772182 16068 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:32.772743 16068 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:32.786731 16068 catalog_manager.cc:6092] T 00000000000000000000000000000000 P b38ae8318f0c4332a653f973fc7df66a: Generated new TSK 0
I20260812 06:18:32.786936 16068 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:32.811167 15750 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:32.813479 16086 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:18:32.813689 15750 server_base.cc:1061] running on GCE node
W20260812 06:18:32.813479 16083 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:18:32.813558 16084 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:18:32.814065 15750 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:32.814126 15750 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:18:32.814150 15750 hybrid_clock.cc:648] HybridClock initialized: now 1786515512814151 us; error 0 us; skew 500 ppm
I20260812 06:18:32.815055 15750 webserver.cc:533] Webserver started at http://127.15.97.129:42657/ using document root <none> and password file <none>
I20260812 06:18:32.815238 15750 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:32.815300 15750 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:32.815357 15750 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:32.815786 15750 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507080306-15750-0/minicluster-data/ts-0-root/instance:
uuid: "d1487ce1f7eb4e07b2d0eed59b37c38d"
format_stamp: "Formatted at 2026-08-12 06:18:32 on dist-test-slave-27sr"
I20260812 06:18:32.817416 15750 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:32.818468 16092 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:18:32.818866 15750 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:32.818965 15750 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507080306-15750-0/minicluster-data/ts-0-root
uuid: "d1487ce1f7eb4e07b2d0eed59b37c38d"
format_stamp: "Formatted at 2026-08-12 06:18:32 on dist-test-slave-27sr"
I20260812 06:18:32.819070 15750 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507080306-15750-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507080306-15750-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507080306-15750-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:18:32.828414 15750 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:32.828858 15750 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:32.829212 15750 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:32.829756 15750 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:32.829824 15750 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:32.829892 15750 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:32.829946 15750 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:32.834606 15750 rpc_server.cc:307] RPC server started. Bound to: 127.15.97.129:43049
I20260812 06:18:32.834641 16165 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.15.97.129:43049 every 8 connection(s)
I20260812 06:18:32.844873 16168 heartbeater.cc:344] Connected to a master server at 127.15.97.190:33475
I20260812 06:18:32.845041 16168 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:32.845288 16168 heartbeater.cc:507] Master 127.15.97.190:33475 requested a full tablet report, sending...
I20260812 06:18:32.846079 16012 ts_manager.cc:194] Registered new tserver with Master: d1487ce1f7eb4e07b2d0eed59b37c38d (127.15.97.129:43049)
I20260812 06:18:32.846221 15750 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011195789s
I20260812 06:18:32.847198 16012 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:58270
I20260812 06:18:32.853863 16012 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:58272:
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:18:32.863317 16126 tablet_service.cc:1511] Processing CreateTablet for tablet db1fa0a0dfc7477f9b688715906a6f0b (DEFAULT_TABLE table=heavy-update-compaction-test [id=4f4d1a21cb43412a8b7afb019681398a]), partition=
I20260812 06:18:32.863642 16126 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet db1fa0a0dfc7477f9b688715906a6f0b. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:32.866072 16184 tablet_bootstrap.cc:492] T db1fa0a0dfc7477f9b688715906a6f0b P d1487ce1f7eb4e07b2d0eed59b37c38d: Bootstrap starting.
I20260812 06:18:32.866989 16184 tablet_bootstrap.cc:654] T db1fa0a0dfc7477f9b688715906a6f0b P d1487ce1f7eb4e07b2d0eed59b37c38d: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:32.868294 16184 tablet_bootstrap.cc:492] T db1fa0a0dfc7477f9b688715906a6f0b P d1487ce1f7eb4e07b2d0eed59b37c38d: No bootstrap required, opened a new log
I20260812 06:18:32.868410 16184 ts_tablet_manager.cc:1403] T db1fa0a0dfc7477f9b688715906a6f0b P d1487ce1f7eb4e07b2d0eed59b37c38d: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:32.868922 16184 raft_consensus.cc:359] T db1fa0a0dfc7477f9b688715906a6f0b P d1487ce1f7eb4e07b2d0eed59b37c38d [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d1487ce1f7eb4e07b2d0eed59b37c38d" member_type: VOTER last_known_addr { host: "127.15.97.129" port: 43049 } }
I20260812 06:18:32.869014 16184 raft_consensus.cc:385] T db1fa0a0dfc7477f9b688715906a6f0b P d1487ce1f7eb4e07b2d0eed59b37c38d [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:32.869036 16184 raft_consensus.cc:740] T db1fa0a0dfc7477f9b688715906a6f0b P d1487ce1f7eb4e07b2d0eed59b37c38d [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: d1487ce1f7eb4e07b2d0eed59b37c38d, State: Initialized, Role: FOLLOWER
I20260812 06:18:32.869132 16184 consensus_queue.cc:260] T db1fa0a0dfc7477f9b688715906a6f0b P d1487ce1f7eb4e07b2d0eed59b37c38d [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: "d1487ce1f7eb4e07b2d0eed59b37c38d" member_type: VOTER last_known_addr { host: "127.15.97.129" port: 43049 } }
I20260812 06:18:32.869191 16184 raft_consensus.cc:399] T db1fa0a0dfc7477f9b688715906a6f0b P d1487ce1f7eb4e07b2d0eed59b37c38d [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:32.869213 16184 raft_consensus.cc:493] T db1fa0a0dfc7477f9b688715906a6f0b P d1487ce1f7eb4e07b2d0eed59b37c38d [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:32.869246 16184 raft_consensus.cc:3060] T db1fa0a0dfc7477f9b688715906a6f0b P d1487ce1f7eb4e07b2d0eed59b37c38d [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:32.869966 16184 raft_consensus.cc:515] T db1fa0a0dfc7477f9b688715906a6f0b P d1487ce1f7eb4e07b2d0eed59b37c38d [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d1487ce1f7eb4e07b2d0eed59b37c38d" member_type: VOTER last_known_addr { host: "127.15.97.129" port: 43049 } }
I20260812 06:18:32.870085 16184 leader_election.cc:304] T db1fa0a0dfc7477f9b688715906a6f0b P d1487ce1f7eb4e07b2d0eed59b37c38d [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: d1487ce1f7eb4e07b2d0eed59b37c38d; no voters: 
I20260812 06:18:32.870246 16184 leader_election.cc:290] T db1fa0a0dfc7477f9b688715906a6f0b P d1487ce1f7eb4e07b2d0eed59b37c38d [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:32.870507 16195 raft_consensus.cc:2804] T db1fa0a0dfc7477f9b688715906a6f0b P d1487ce1f7eb4e07b2d0eed59b37c38d [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:32.870553 16184 ts_tablet_manager.cc:1434] T db1fa0a0dfc7477f9b688715906a6f0b P d1487ce1f7eb4e07b2d0eed59b37c38d: Time spent starting tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:32.870602 16168 heartbeater.cc:499] Master 127.15.97.190:33475 was elected leader, sending a full tablet report...
I20260812 06:18:32.870735 16195 raft_consensus.cc:697] T db1fa0a0dfc7477f9b688715906a6f0b P d1487ce1f7eb4e07b2d0eed59b37c38d [term 1 LEADER]: Becoming Leader. State: Replica: d1487ce1f7eb4e07b2d0eed59b37c38d, State: Running, Role: LEADER
I20260812 06:18:32.870877 16195 consensus_queue.cc:237] T db1fa0a0dfc7477f9b688715906a6f0b P d1487ce1f7eb4e07b2d0eed59b37c38d [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: "d1487ce1f7eb4e07b2d0eed59b37c38d" member_type: VOTER last_known_addr { host: "127.15.97.129" port: 43049 } }
I20260812 06:18:32.872438 16012 catalog_manager.cc:5719] T db1fa0a0dfc7477f9b688715906a6f0b P d1487ce1f7eb4e07b2d0eed59b37c38d reported cstate change: term changed from 0 to 1, leader changed from <none> to d1487ce1f7eb4e07b2d0eed59b37c38d (127.15.97.129). New cstate: current_term: 1 leader_uuid: "d1487ce1f7eb4e07b2d0eed59b37c38d" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d1487ce1f7eb4e07b2d0eed59b37c38d" member_type: VOTER last_known_addr { host: "127.15.97.129" port: 43049 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:32.934904 15750 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.056s	user 0.013s	sys 0.012s
I20260812 06:18:33.085732 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling FlushMRSOp(db1fa0a0dfc7477f9b688715906a6f0b): perf score=19.054940
I20260812 06:18:33.250342 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: FlushMRSOp(db1fa0a0dfc7477f9b688715906a6f0b) complete. Timing: real 0.164s	user 0.101s	sys 0.060s Metrics: {"bytes_written":12307489,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":70,"dirs.run_cpu_time_us":198,"dirs.run_wall_time_us":1093,"drs_written":1,"lbm_read_time_us":65,"lbm_reads_lt_1ms":4,"lbm_write_time_us":44236,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:18:33.251120 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling LogGCOp(db1fa0a0dfc7477f9b688715906a6f0b): free 20743880 bytes of WAL
I20260812 06:18:33.251374 16098 log_reader.cc:385] T db1fa0a0dfc7477f9b688715906a6f0b: removed 2 log segments from log reader
I20260812 06:18:33.251446 16098 log.cc:1079] T db1fa0a0dfc7477f9b688715906a6f0b P d1487ce1f7eb4e07b2d0eed59b37c38d: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/db1fa0a0dfc7477f9b688715906a6f0b/wal-000000001 (ops 1-6)
I20260812 06:18:33.251502 16098 log.cc:1079] T db1fa0a0dfc7477f9b688715906a6f0b P d1487ce1f7eb4e07b2d0eed59b37c38d: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/db1fa0a0dfc7477f9b688715906a6f0b/wal-000000002 (ops 7-11)
I20260812 06:18:33.255822 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: LogGCOp(db1fa0a0dfc7477f9b688715906a6f0b) complete. Timing: real 0.004s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:18:33.256362 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b): perf score=2.188937
I20260812 06:18:33.275072 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b) complete. Timing: real 0.018s	user 0.001s	sys 0.013s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6047,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:33.275720 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling UndoDeltaBlockGCOp(db1fa0a0dfc7477f9b688715906a6f0b): 16411393 bytes on disk
I20260812 06:18:33.276273 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: UndoDeltaBlockGCOp(db1fa0a0dfc7477f9b688715906a6f0b) 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:18:33.276686 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling MajorDeltaCompactionOp(db1fa0a0dfc7477f9b688715906a6f0b): perf score=1.000000
I20260812 06:18:33.449476 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: MajorDeltaCompactionOp(db1fa0a0dfc7477f9b688715906a6f0b) complete. Timing: real 0.173s	user 0.111s	sys 0.057s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":651,"lbm_read_time_us":11793,"lbm_reads_lt_1ms":460,"lbm_write_time_us":25110,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":324,"threads_started":5,"update_count":2000}
I20260812 06:18:33.450116 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b): perf score=14.095187
I20260812 06:18:33.500147 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b) complete. Timing: real 0.050s	user 0.042s	sys 0.004s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20794,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:33.500663 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b): perf score=2.188937
I20260812 06:18:33.512666 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4072,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:33.513406 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling MajorDeltaCompactionOp(db1fa0a0dfc7477f9b688715906a6f0b): perf score=1.000000
I20260812 06:18:33.666734 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: MajorDeltaCompactionOp(db1fa0a0dfc7477f9b688715906a6f0b) complete. Timing: real 0.153s	user 0.095s	sys 0.055s 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":426,"lbm_read_time_us":10175,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32247,"lbm_writes_lt_1ms":543,"mutex_wait_us":1,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:18:33.667354 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b): perf score=10.126437
I20260812 06:18:33.700922 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b) complete. Timing: real 0.033s	user 0.022s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14094,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:33.701418 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling MajorDeltaCompactionOp(db1fa0a0dfc7477f9b688715906a6f0b): perf score=1.000000
I20260812 06:18:33.805467 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: MajorDeltaCompactionOp(db1fa0a0dfc7477f9b688715906a6f0b) complete. Timing: real 0.104s	user 0.065s	sys 0.039s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569746,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":202,"lbm_read_time_us":6894,"lbm_reads_lt_1ms":363,"lbm_write_time_us":19495,"lbm_writes_lt_1ms":343,"mutex_wait_us":29,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":81152,"update_count":1500}
I20260812 06:18:33.806087 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b): perf score=10.126437
I20260812 06:18:33.856199 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b) complete. Timing: real 0.050s	user 0.030s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18617,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:33.856756 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b): perf score=2.188937
I20260812 06:18:33.868436 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b) complete. Timing: real 0.011s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4129,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:33.869154 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling MajorDeltaCompactionOp(db1fa0a0dfc7477f9b688715906a6f0b): perf score=1.000000
I20260812 06:18:34.008622 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: MajorDeltaCompactionOp(db1fa0a0dfc7477f9b688715906a6f0b) complete. Timing: real 0.139s	user 0.103s	sys 0.035s 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":1053,"lbm_read_time_us":9109,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27000,"lbm_writes_lt_1ms":443,"mutex_wait_us":364,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":53376,"update_count":2000}
I20260812 06:18:34.009361 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b): perf score=10.126437
I20260812 06:18:34.057374 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b) complete. Timing: real 0.048s	user 0.032s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18262,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:34.057837 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b): perf score=2.188937
I20260812 06:18:34.069406 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4538,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:34.070209 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling MajorDeltaCompactionOp(db1fa0a0dfc7477f9b688715906a6f0b): perf score=1.000000
I20260812 06:18:34.200594 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: MajorDeltaCompactionOp(db1fa0a0dfc7477f9b688715906a6f0b) complete. Timing: real 0.130s	user 0.098s	sys 0.031s 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":163,"lbm_read_time_us":9608,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25917,"lbm_writes_lt_1ms":443,"mutex_wait_us":22,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5632,"update_count":2000}
I20260812 06:18:34.201226 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b): perf score=10.126437
I20260812 06:18:34.240329 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b) complete. Timing: real 0.039s	user 0.020s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14011,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:34.240914 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling MajorDeltaCompactionOp(db1fa0a0dfc7477f9b688715906a6f0b): perf score=1.000000
I20260812 06:18:34.353600 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: MajorDeltaCompactionOp(db1fa0a0dfc7477f9b688715906a6f0b) complete. Timing: real 0.113s	user 0.087s	sys 0.024s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569746,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1340,"lbm_read_time_us":8561,"lbm_reads_lt_1ms":363,"lbm_write_time_us":22638,"lbm_writes_lt_1ms":343,"mutex_wait_us":387,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":2048,"update_count":1500}
I20260812 06:18:34.354079 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b): perf score=10.126437
I20260812 06:18:34.400990 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b) complete. Timing: real 0.047s	user 0.026s	sys 0.007s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15100,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:34.401559 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b): perf score=2.188937
I20260812 06:18:34.412791 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3966,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:34.413458 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling MajorDeltaCompactionOp(db1fa0a0dfc7477f9b688715906a6f0b): perf score=1.000000
I20260812 06:18:34.547988 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: MajorDeltaCompactionOp(db1fa0a0dfc7477f9b688715906a6f0b) complete. Timing: real 0.134s	user 0.085s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1357,"lbm_read_time_us":9434,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24092,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":28160,"update_count":2000}
I20260812 06:18:34.548661 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b): perf score=10.126437
I20260812 06:18:34.590664 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b) complete. Timing: real 0.042s	user 0.016s	sys 0.024s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":18842,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:34.591317 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b): perf score=2.188937
I20260812 06:18:34.603772 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4294,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:34.604324 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling FlushMRSOp(db1fa0a0dfc7477f9b688715906a6f0b): perf score=1.000000
I20260812 06:18:34.631197 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: FlushMRSOp(db1fa0a0dfc7477f9b688715906a6f0b) complete. Timing: real 0.027s	user 0.025s	sys 0.000s Metrics: {"bytes_written":1275443,"cfile_init":1,"dirs.queue_time_us":101,"dirs.run_cpu_time_us":269,"dirs.run_wall_time_us":1442,"drs_written":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1507,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:34.631793 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling LogGCOp(db1fa0a0dfc7477f9b688715906a6f0b): free 128867389 bytes of WAL
I20260812 06:18:34.632045 16098 log_reader.cc:385] T db1fa0a0dfc7477f9b688715906a6f0b: removed 13 log segments from log reader
I20260812 06:18:34.632110 16098 log.cc:1079] T db1fa0a0dfc7477f9b688715906a6f0b P d1487ce1f7eb4e07b2d0eed59b37c38d: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/db1fa0a0dfc7477f9b688715906a6f0b/wal-000000003 (ops 12-16)
I20260812 06:18:34.632162 16098 log.cc:1079] T db1fa0a0dfc7477f9b688715906a6f0b P d1487ce1f7eb4e07b2d0eed59b37c38d: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/db1fa0a0dfc7477f9b688715906a6f0b/wal-000000004 (ops 17-20)
I20260812 06:18:34.632220 16098 log.cc:1079] T db1fa0a0dfc7477f9b688715906a6f0b P d1487ce1f7eb4e07b2d0eed59b37c38d: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/db1fa0a0dfc7477f9b688715906a6f0b/wal-000000005 (ops 21-25)
I20260812 06:18:34.632269 16098 log.cc:1079] T db1fa0a0dfc7477f9b688715906a6f0b P d1487ce1f7eb4e07b2d0eed59b37c38d: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/db1fa0a0dfc7477f9b688715906a6f0b/wal-000000006 (ops 26-30)
I20260812 06:18:34.632305 16098 log.cc:1079] T db1fa0a0dfc7477f9b688715906a6f0b P d1487ce1f7eb4e07b2d0eed59b37c38d: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/db1fa0a0dfc7477f9b688715906a6f0b/wal-000000007 (ops 31-35)
I20260812 06:18:34.632344 16098 log.cc:1079] T db1fa0a0dfc7477f9b688715906a6f0b P d1487ce1f7eb4e07b2d0eed59b37c38d: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/db1fa0a0dfc7477f9b688715906a6f0b/wal-000000008 (ops 36-40)
I20260812 06:18:34.632380 16098 log.cc:1079] T db1fa0a0dfc7477f9b688715906a6f0b P d1487ce1f7eb4e07b2d0eed59b37c38d: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/db1fa0a0dfc7477f9b688715906a6f0b/wal-000000009 (ops 41-45)
I20260812 06:18:34.632418 16098 log.cc:1079] T db1fa0a0dfc7477f9b688715906a6f0b P d1487ce1f7eb4e07b2d0eed59b37c38d: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/db1fa0a0dfc7477f9b688715906a6f0b/wal-000000010 (ops 46-50)
I20260812 06:18:34.632455 16098 log.cc:1079] T db1fa0a0dfc7477f9b688715906a6f0b P d1487ce1f7eb4e07b2d0eed59b37c38d: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/db1fa0a0dfc7477f9b688715906a6f0b/wal-000000011 (ops 51-54)
I20260812 06:18:34.632491 16098 log.cc:1079] T db1fa0a0dfc7477f9b688715906a6f0b P d1487ce1f7eb4e07b2d0eed59b37c38d: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/db1fa0a0dfc7477f9b688715906a6f0b/wal-000000012 (ops 55-59)
I20260812 06:18:34.632529 16098 log.cc:1079] T db1fa0a0dfc7477f9b688715906a6f0b P d1487ce1f7eb4e07b2d0eed59b37c38d: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/db1fa0a0dfc7477f9b688715906a6f0b/wal-000000013 (ops 60-64)
I20260812 06:18:34.632565 16098 log.cc:1079] T db1fa0a0dfc7477f9b688715906a6f0b P d1487ce1f7eb4e07b2d0eed59b37c38d: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/db1fa0a0dfc7477f9b688715906a6f0b/wal-000000014 (ops 65-68)
I20260812 06:18:34.632599 16098 log.cc:1079] T db1fa0a0dfc7477f9b688715906a6f0b P d1487ce1f7eb4e07b2d0eed59b37c38d: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/db1fa0a0dfc7477f9b688715906a6f0b/wal-000000015 (ops 69-73)
I20260812 06:18:34.664587 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: LogGCOp(db1fa0a0dfc7477f9b688715906a6f0b) complete. Timing: real 0.033s	user 0.000s	sys 0.032s Metrics: {}
I20260812 06:18:34.665151 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b): perf score=4.173312
I20260812 06:18:34.683416 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b) complete. Timing: real 0.018s	user 0.007s	sys 0.009s Metrics: {"bytes_written":5866705,"delete_count":0,"lbm_write_time_us":7695,"lbm_writes_lt_1ms":146,"reinsert_count":0,"update_count":715}
I20260812 06:18:34.683964 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling UndoDeltaBlockGCOp(db1fa0a0dfc7477f9b688715906a6f0b): 483 bytes on disk
I20260812 06:18:34.684398 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: UndoDeltaBlockGCOp(db1fa0a0dfc7477f9b688715906a6f0b) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4}
I20260812 06:18:34.684926 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b): perf score=1.196750
I20260812 06:18:34.693872 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b) complete. Timing: real 0.009s	user 0.006s	sys 0.001s Metrics: {"bytes_written":2338579,"delete_count":0,"lbm_write_time_us":2656,"lbm_writes_lt_1ms":60,"reinsert_count":0,"update_count":285}
I20260812 06:18:34.694439 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling MajorDeltaCompactionOp(db1fa0a0dfc7477f9b688715906a6f0b): perf score=1.000000
I20260812 06:18:34.873407 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: MajorDeltaCompactionOp(db1fa0a0dfc7477f9b688715906a6f0b) complete. Timing: real 0.179s	user 0.143s	sys 0.035s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877301,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":871,"lbm_read_time_us":13072,"lbm_reads_lt_1ms":674,"lbm_write_time_us":33610,"lbm_writes_lt_1ms":643,"mutex_wait_us":64,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":52352,"thread_start_us":80,"threads_started":1,"update_count":3000}
I20260812 06:18:34.874161 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b): perf score=14.095187
I20260812 06:18:34.919540 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b) complete. Timing: real 0.045s	user 0.029s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19665,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:34.920190 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b): perf score=2.188937
I20260812 06:18:34.947237 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b) complete. Timing: real 0.027s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5961,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:34.947695 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b): perf score=2.188937
I20260812 06:18:34.958420 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4023,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:34.958890 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling MajorDeltaCompactionOp(db1fa0a0dfc7477f9b688715906a6f0b): perf score=1.000000
I20260812 06:18:35.184710 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: MajorDeltaCompactionOp(db1fa0a0dfc7477f9b688715906a6f0b) complete. Timing: real 0.226s	user 0.165s	sys 0.056s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877219,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":275,"lbm_read_time_us":14388,"lbm_reads_lt_1ms":673,"lbm_write_time_us":36690,"lbm_writes_lt_1ms":643,"mutex_wait_us":32,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":23552,"update_count":3000}
I20260812 06:18:35.185449 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b): perf score=14.095187
I20260812 06:18:35.237177 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b) complete. Timing: real 0.051s	user 0.022s	sys 0.028s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":23497,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:35.237664 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b): perf score=2.188937
I20260812 06:18:35.250057 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4243,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:35.250579 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling MajorDeltaCompactionOp(db1fa0a0dfc7477f9b688715906a6f0b): perf score=1.000000
I20260812 06:18:35.457762 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: MajorDeltaCompactionOp(db1fa0a0dfc7477f9b688715906a6f0b) complete. Timing: real 0.207s	user 0.156s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":233,"lbm_read_time_us":13575,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34376,"lbm_writes_lt_1ms":543,"mutex_wait_us":47,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":15360,"update_count":2500}
I20260812 06:18:35.458632 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b): perf score=10.126437
I20260812 06:18:35.506313 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b) complete. Timing: real 0.047s	user 0.033s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":21331,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:18:35.506902 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b): perf score=2.188937
I20260812 06:18:35.532826 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b) complete. Timing: real 0.026s	user 0.012s	sys 0.001s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5435,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:35.533356 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b): perf score=2.188937
I20260812 06:18:35.544251 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4043,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:35.544852 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling MajorDeltaCompactionOp(db1fa0a0dfc7477f9b688715906a6f0b): perf score=1.000000
I20260812 06:18:35.706156 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: MajorDeltaCompactionOp(db1fa0a0dfc7477f9b688715906a6f0b) complete. Timing: real 0.161s	user 0.119s	sys 0.040s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774807,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":350,"lbm_read_time_us":9638,"lbm_reads_lt_1ms":573,"lbm_write_time_us":32963,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2500}
I20260812 06:18:35.706959 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b): perf score=10.126437
I20260812 06:18:35.745146 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b) complete. Timing: real 0.038s	user 0.021s	sys 0.015s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16493,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:35.745900 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b): perf score=2.188937
I20260812 06:18:35.763213 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b) complete. Timing: real 0.017s	user 0.011s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6436,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:35.763662 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling MajorDeltaCompactionOp(db1fa0a0dfc7477f9b688715906a6f0b): perf score=1.000000
I20260812 06:18:35.896788 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: MajorDeltaCompactionOp(db1fa0a0dfc7477f9b688715906a6f0b) complete. Timing: real 0.133s	user 0.105s	sys 0.027s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":703,"lbm_read_time_us":10061,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25108,"lbm_writes_lt_1ms":443,"mutex_wait_us":21,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":19072,"update_count":2000}
I20260812 06:18:35.897495 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b): perf score=10.126437
I20260812 06:18:35.940485 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b) complete. Timing: real 0.043s	user 0.025s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16615,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:35.940968 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b): perf score=2.188937
I20260812 06:18:35.953984 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b) complete. Timing: real 0.013s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4494,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:35.954640 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling MajorDeltaCompactionOp(db1fa0a0dfc7477f9b688715906a6f0b): perf score=1.000000
I20260812 06:18:36.098991 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: MajorDeltaCompactionOp(db1fa0a0dfc7477f9b688715906a6f0b) complete. Timing: real 0.144s	user 0.118s	sys 0.021s 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":437,"lbm_read_time_us":9166,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26645,"lbm_writes_lt_1ms":443,"mutex_wait_us":27,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":20480,"update_count":2000}
I20260812 06:18:36.099943 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b): perf score=11.118625
I20260812 06:18:36.151181 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b) complete. Timing: real 0.051s	user 0.028s	sys 0.020s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":20646,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":311,"reinsert_count":0,"update_count":1550}
I20260812 06:18:36.151823 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b): perf score=2.188937
I20260812 06:18:36.167454 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b) complete. Timing: real 0.015s	user 0.009s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4631,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:36.168134 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b): perf score=2.188937
I20260812 06:18:36.178892 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4088,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:36.179425 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling FlushMRSOp(db1fa0a0dfc7477f9b688715906a6f0b): perf score=1.000000
I20260812 06:18:36.213332 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: FlushMRSOp(db1fa0a0dfc7477f9b688715906a6f0b) complete. Timing: real 0.034s	user 0.028s	sys 0.004s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":83,"dirs.run_cpu_time_us":275,"dirs.run_wall_time_us":1501,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1466,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:36.214020 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling LogGCOp(db1fa0a0dfc7477f9b688715906a6f0b): free 128867482 bytes of WAL
I20260812 06:18:36.214303 16098 log_reader.cc:385] T db1fa0a0dfc7477f9b688715906a6f0b: removed 13 log segments from log reader
I20260812 06:18:36.214365 16098 log.cc:1079] T db1fa0a0dfc7477f9b688715906a6f0b P d1487ce1f7eb4e07b2d0eed59b37c38d: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/db1fa0a0dfc7477f9b688715906a6f0b/wal-000000016 (ops 74-78)
I20260812 06:18:36.214401 16098 log.cc:1079] T db1fa0a0dfc7477f9b688715906a6f0b P d1487ce1f7eb4e07b2d0eed59b37c38d: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/db1fa0a0dfc7477f9b688715906a6f0b/wal-000000017 (ops 79-83)
I20260812 06:18:36.214438 16098 log.cc:1079] T db1fa0a0dfc7477f9b688715906a6f0b P d1487ce1f7eb4e07b2d0eed59b37c38d: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/db1fa0a0dfc7477f9b688715906a6f0b/wal-000000018 (ops 84-88)
I20260812 06:18:36.214470 16098 log.cc:1079] T db1fa0a0dfc7477f9b688715906a6f0b P d1487ce1f7eb4e07b2d0eed59b37c38d: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/db1fa0a0dfc7477f9b688715906a6f0b/wal-000000019 (ops 89-92)
I20260812 06:18:36.214496 16098 log.cc:1079] T db1fa0a0dfc7477f9b688715906a6f0b P d1487ce1f7eb4e07b2d0eed59b37c38d: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/db1fa0a0dfc7477f9b688715906a6f0b/wal-000000020 (ops 93-97)
I20260812 06:18:36.214522 16098 log.cc:1079] T db1fa0a0dfc7477f9b688715906a6f0b P d1487ce1f7eb4e07b2d0eed59b37c38d: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/db1fa0a0dfc7477f9b688715906a6f0b/wal-000000021 (ops 98-102)
I20260812 06:18:36.214548 16098 log.cc:1079] T db1fa0a0dfc7477f9b688715906a6f0b P d1487ce1f7eb4e07b2d0eed59b37c38d: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/db1fa0a0dfc7477f9b688715906a6f0b/wal-000000022 (ops 103-107)
I20260812 06:18:36.214581 16098 log.cc:1079] T db1fa0a0dfc7477f9b688715906a6f0b P d1487ce1f7eb4e07b2d0eed59b37c38d: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/db1fa0a0dfc7477f9b688715906a6f0b/wal-000000023 (ops 108-112)
I20260812 06:18:36.214614 16098 log.cc:1079] T db1fa0a0dfc7477f9b688715906a6f0b P d1487ce1f7eb4e07b2d0eed59b37c38d: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/db1fa0a0dfc7477f9b688715906a6f0b/wal-000000024 (ops 113-116)
I20260812 06:18:36.214644 16098 log.cc:1079] T db1fa0a0dfc7477f9b688715906a6f0b P d1487ce1f7eb4e07b2d0eed59b37c38d: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/db1fa0a0dfc7477f9b688715906a6f0b/wal-000000025 (ops 117-121)
I20260812 06:18:36.214672 16098 log.cc:1079] T db1fa0a0dfc7477f9b688715906a6f0b P d1487ce1f7eb4e07b2d0eed59b37c38d: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/db1fa0a0dfc7477f9b688715906a6f0b/wal-000000026 (ops 122-126)
I20260812 06:18:36.214697 16098 log.cc:1079] T db1fa0a0dfc7477f9b688715906a6f0b P d1487ce1f7eb4e07b2d0eed59b37c38d: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/db1fa0a0dfc7477f9b688715906a6f0b/wal-000000027 (ops 127-130)
I20260812 06:18:36.214725 16098 log.cc:1079] T db1fa0a0dfc7477f9b688715906a6f0b P d1487ce1f7eb4e07b2d0eed59b37c38d: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/db1fa0a0dfc7477f9b688715906a6f0b/wal-000000028 (ops 131-135)
I20260812 06:18:36.248937 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: LogGCOp(db1fa0a0dfc7477f9b688715906a6f0b) complete. Timing: real 0.035s	user 0.000s	sys 0.034s Metrics: {}
I20260812 06:18:36.249442 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling UndoDeltaBlockGCOp(db1fa0a0dfc7477f9b688715906a6f0b): 481 bytes on disk
I20260812 06:18:36.249960 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: UndoDeltaBlockGCOp(db1fa0a0dfc7477f9b688715906a6f0b) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4}
I20260812 06:18:36.250506 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b): perf score=2.188937
I20260812 06:18:36.275161 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b) complete. Timing: real 0.024s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5334,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:36.275624 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b): perf score=2.188937
I20260812 06:18:36.286278 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3935,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:36.286768 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling MajorDeltaCompactionOp(db1fa0a0dfc7477f9b688715906a6f0b): perf score=1.000000
I20260812 06:18:36.511972 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: MajorDeltaCompactionOp(db1fa0a0dfc7477f9b688715906a6f0b) complete. Timing: real 0.225s	user 0.162s	sys 0.060s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979859,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":578,"lbm_read_time_us":17005,"lbm_reads_lt_1ms":775,"lbm_write_time_us":37628,"lbm_writes_lt_1ms":743,"mutex_wait_us":264,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":9600,"thread_start_us":79,"threads_started":1,"update_count":3500}
I20260812 06:18:36.513082 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b): perf score=18.063937
I20260812 06:18:36.577701 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b) complete. Timing: real 0.064s	user 0.044s	sys 0.019s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":29046,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:36.578322 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b): perf score=2.188937
I20260812 06:18:36.594816 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b) complete. Timing: real 0.016s	user 0.007s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6442,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:36.595325 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling MajorDeltaCompactionOp(db1fa0a0dfc7477f9b688715906a6f0b): perf score=1.000000
I20260812 06:18:36.757345 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: MajorDeltaCompactionOp(db1fa0a0dfc7477f9b688715906a6f0b) complete. Timing: real 0.162s	user 0.132s	sys 0.030s 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":143,"lbm_read_time_us":11545,"lbm_reads_lt_1ms":672,"lbm_write_time_us":35170,"lbm_writes_lt_1ms":643,"mutex_wait_us":24,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":37376,"update_count":3000}
I20260812 06:18:36.758052 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b): perf score=14.095187
I20260812 06:18:36.808548 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b) complete. Timing: real 0.050s	user 0.033s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21622,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:36.809217 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b): perf score=2.188937
I20260812 06:18:36.827771 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b) complete. Timing: real 0.018s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6966,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:36.828382 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling MajorDeltaCompactionOp(db1fa0a0dfc7477f9b688715906a6f0b): perf score=1.000000
I20260812 06:18:37.009608 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: MajorDeltaCompactionOp(db1fa0a0dfc7477f9b688715906a6f0b) complete. Timing: real 0.181s	user 0.131s	sys 0.034s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":273,"lbm_read_time_us":11346,"lbm_reads_lt_1ms":564,"lbm_write_time_us":35085,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7808,"update_count":2500}
I20260812 06:18:37.010583 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b): perf score=14.095187
I20260812 06:18:37.073771 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b) complete. Timing: real 0.063s	user 0.035s	sys 0.013s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21663,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:37.074373 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b): perf score=2.188937
I20260812 06:18:37.090417 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b) complete. Timing: real 0.016s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5715,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:37.091121 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling MajorDeltaCompactionOp(db1fa0a0dfc7477f9b688715906a6f0b): perf score=1.000000
I20260812 06:18:37.286906 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: MajorDeltaCompactionOp(db1fa0a0dfc7477f9b688715906a6f0b) complete. Timing: real 0.196s	user 0.144s	sys 0.048s 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":712,"lbm_read_time_us":13955,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33196,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9600,"update_count":2500}
I20260812 06:18:37.287532 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b): perf score=14.095187
I20260812 06:18:37.340426 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b) complete. Timing: real 0.053s	user 0.037s	sys 0.015s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":23740,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:37.340916 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling MajorDeltaCompactionOp(db1fa0a0dfc7477f9b688715906a6f0b): perf score=1.000000
I20260812 06:18:37.501394 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: MajorDeltaCompactionOp(db1fa0a0dfc7477f9b688715906a6f0b) complete. Timing: real 0.160s	user 0.108s	sys 0.041s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672154,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":357,"lbm_read_time_us":9184,"lbm_reads_lt_1ms":467,"lbm_write_time_us":24488,"lbm_writes_lt_1ms":443,"mutex_wait_us":70,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9216,"update_count":2000}
I20260812 06:18:37.502157 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b): perf score=14.095187
I20260812 06:18:37.559211 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b) complete. Timing: real 0.057s	user 0.026s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24115,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:37.559796 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b): perf score=2.188937
I20260812 06:18:37.571575 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4129,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:37.572171 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling MajorDeltaCompactionOp(db1fa0a0dfc7477f9b688715906a6f0b): perf score=1.000000
I20260812 06:18:37.761404 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: MajorDeltaCompactionOp(db1fa0a0dfc7477f9b688715906a6f0b) complete. Timing: real 0.189s	user 0.144s	sys 0.045s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":621,"lbm_read_time_us":13391,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30445,"lbm_writes_lt_1ms":543,"mutex_wait_us":48,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":2500}
I20260812 06:18:37.762253 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b): perf score=14.095187
I20260812 06:18:37.814082 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b) complete. Timing: real 0.052s	user 0.018s	sys 0.032s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23134,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:37.814702 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b): perf score=2.188937
I20260812 06:18:37.839711 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b) complete. Timing: real 0.025s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5572,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:37.840238 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b): perf score=2.188937
I20260812 06:18:37.860533 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b) complete. Timing: real 0.020s	user 0.009s	sys 0.010s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4072,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:37.861110 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling FlushMRSOp(db1fa0a0dfc7477f9b688715906a6f0b): perf score=1.000000
I20260812 06:18:37.908316 15750 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.973s	user 1.886s	sys 0.133s
I20260812 06:18:37.910305 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: FlushMRSOp(db1fa0a0dfc7477f9b688715906a6f0b) complete. Timing: real 0.049s	user 0.029s	sys 0.005s Metrics: {"bytes_written":1357582,"cfile_init":1,"dirs.queue_time_us":78,"dirs.run_cpu_time_us":278,"dirs.run_wall_time_us":1392,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1848,"lbm_writes_lt_1ms":44,"peak_mem_usage":0,"rows_written":33}
I20260812 06:18:37.910983 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling LogGCOp(db1fa0a0dfc7477f9b688715906a6f0b): free 132571642 bytes of WAL
I20260812 06:18:37.911223 16098 log_reader.cc:385] T db1fa0a0dfc7477f9b688715906a6f0b: removed 13 log segments from log reader
I20260812 06:18:37.911271 16098 log.cc:1079] T db1fa0a0dfc7477f9b688715906a6f0b P d1487ce1f7eb4e07b2d0eed59b37c38d: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/db1fa0a0dfc7477f9b688715906a6f0b/wal-000000029 (ops 136-140)
I20260812 06:18:37.911298 16098 log.cc:1079] T db1fa0a0dfc7477f9b688715906a6f0b P d1487ce1f7eb4e07b2d0eed59b37c38d: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/db1fa0a0dfc7477f9b688715906a6f0b/wal-000000030 (ops 141-144)
I20260812 06:18:37.911360 16098 log.cc:1079] T db1fa0a0dfc7477f9b688715906a6f0b P d1487ce1f7eb4e07b2d0eed59b37c38d: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/db1fa0a0dfc7477f9b688715906a6f0b/wal-000000031 (ops 145-149)
I20260812 06:18:37.911398 16098 log.cc:1079] T db1fa0a0dfc7477f9b688715906a6f0b P d1487ce1f7eb4e07b2d0eed59b37c38d: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/db1fa0a0dfc7477f9b688715906a6f0b/wal-000000032 (ops 150-154)
I20260812 06:18:37.911437 16098 log.cc:1079] T db1fa0a0dfc7477f9b688715906a6f0b P d1487ce1f7eb4e07b2d0eed59b37c38d: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/db1fa0a0dfc7477f9b688715906a6f0b/wal-000000033 (ops 155-159)
I20260812 06:18:37.911477 16098 log.cc:1079] T db1fa0a0dfc7477f9b688715906a6f0b P d1487ce1f7eb4e07b2d0eed59b37c38d: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/db1fa0a0dfc7477f9b688715906a6f0b/wal-000000034 (ops 160-164)
I20260812 06:18:37.911517 16098 log.cc:1079] T db1fa0a0dfc7477f9b688715906a6f0b P d1487ce1f7eb4e07b2d0eed59b37c38d: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/db1fa0a0dfc7477f9b688715906a6f0b/wal-000000035 (ops 165-169)
I20260812 06:18:37.911556 16098 log.cc:1079] T db1fa0a0dfc7477f9b688715906a6f0b P d1487ce1f7eb4e07b2d0eed59b37c38d: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/db1fa0a0dfc7477f9b688715906a6f0b/wal-000000036 (ops 170-174)
I20260812 06:18:37.911592 16098 log.cc:1079] T db1fa0a0dfc7477f9b688715906a6f0b P d1487ce1f7eb4e07b2d0eed59b37c38d: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/db1fa0a0dfc7477f9b688715906a6f0b/wal-000000037 (ops 175-179)
I20260812 06:18:37.911633 16098 log.cc:1079] T db1fa0a0dfc7477f9b688715906a6f0b P d1487ce1f7eb4e07b2d0eed59b37c38d: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/db1fa0a0dfc7477f9b688715906a6f0b/wal-000000038 (ops 180-184)
I20260812 06:18:37.911674 16098 log.cc:1079] T db1fa0a0dfc7477f9b688715906a6f0b P d1487ce1f7eb4e07b2d0eed59b37c38d: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/db1fa0a0dfc7477f9b688715906a6f0b/wal-000000039 (ops 185-189)
I20260812 06:18:37.911710 16098 log.cc:1079] T db1fa0a0dfc7477f9b688715906a6f0b P d1487ce1f7eb4e07b2d0eed59b37c38d: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/db1fa0a0dfc7477f9b688715906a6f0b/wal-000000040 (ops 190-194)
I20260812 06:18:37.911779 16098 log.cc:1079] T db1fa0a0dfc7477f9b688715906a6f0b P d1487ce1f7eb4e07b2d0eed59b37c38d: Deleting log segment in path: /tmp/dist-test-taskL2eUrE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507080306-15750-0/minicluster-data/ts-0-root/wals/db1fa0a0dfc7477f9b688715906a6f0b/wal-000000041 (ops 195-198)
I20260812 06:18:37.940634 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: LogGCOp(db1fa0a0dfc7477f9b688715906a6f0b) complete. Timing: real 0.029s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:18:37.941183 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b): perf score=2.188937
I20260812 06:18:37.952965 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: FlushDeltaMemStoresOp(db1fa0a0dfc7477f9b688715906a6f0b) complete. Timing: real 0.012s	user 0.004s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4863,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:37.953415 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling UndoDeltaBlockGCOp(db1fa0a0dfc7477f9b688715906a6f0b): 508 bytes on disk
I20260812 06:18:37.953873 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: UndoDeltaBlockGCOp(db1fa0a0dfc7477f9b688715906a6f0b) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":72,"lbm_reads_lt_1ms":4}
I20260812 06:18:37.954401 16170 maintenance_manager.cc:419] P d1487ce1f7eb4e07b2d0eed59b37c38d: Scheduling MajorDeltaCompactionOp(db1fa0a0dfc7477f9b688715906a6f0b): perf score=1.000000
I20260812 06:18:37.995709 15750 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.087s	user 0.000s	sys 0.000s
I20260812 06:18:37.996333 15750 tablet_server.cc:179] TabletServer@127.15.97.129:0 shutting down...
I20260812 06:18:38.106746 16098 maintenance_manager.cc:643] P d1487ce1f7eb4e07b2d0eed59b37c38d: MajorDeltaCompactionOp(db1fa0a0dfc7477f9b688715906a6f0b) complete. Timing: real 0.152s	user 0.111s	sys 0.040s Metrics: {"cfile_cache_hit":609,"cfile_cache_hit_bytes":25467308,"cfile_cache_miss":125,"cfile_cache_miss_bytes":7512443,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":456,"lbm_read_time_us":4344,"lbm_reads_lt_1ms":153,"lbm_write_time_us":34320,"lbm_writes_lt_1ms":743,"mutex_wait_us":85,"peak_mem_usage":87969044,"reinsert_count":0,"thread_start_us":105,"threads_started":1,"update_count":3500}
I20260812 06:18:38.107486 15750 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:38.107686 15750 tablet_replica.cc:333] T db1fa0a0dfc7477f9b688715906a6f0b P d1487ce1f7eb4e07b2d0eed59b37c38d: stopping tablet replica
I20260812 06:18:38.107810 15750 raft_consensus.cc:2243] T db1fa0a0dfc7477f9b688715906a6f0b P d1487ce1f7eb4e07b2d0eed59b37c38d [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:38.107995 15750 raft_consensus.cc:2272] T db1fa0a0dfc7477f9b688715906a6f0b P d1487ce1f7eb4e07b2d0eed59b37c38d [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:38.112427 15750 tablet_server.cc:196] TabletServer@127.15.97.129:0 shutdown complete.
I20260812 06:18:38.165678 15750 master.cc:562] Master@127.15.97.190:33475 shutting down...
I20260812 06:18:38.170104 15750 raft_consensus.cc:2243] T 00000000000000000000000000000000 P b38ae8318f0c4332a653f973fc7df66a [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:38.170331 15750 raft_consensus.cc:2272] T 00000000000000000000000000000000 P b38ae8318f0c4332a653f973fc7df66a [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:38.170423 15750 tablet_replica.cc:333] T 00000000000000000000000000000000 P b38ae8318f0c4332a653f973fc7df66a: stopping tablet replica
I20260812 06:18:38.183027 15750 master.cc:584] Master@127.15.97.190:33475 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5577 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11182 ms total)

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