[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:17:40.828768 18432 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.18.0.62:33217
I20260812 06:17:40.829849 18432 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:17:40.830511 18432 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:17:40.837491 18432 server_base.cc:1061] running on GCE node
W20260812 06:17:40.837590 18442 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:40.837567 18445 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:40.837806 18441 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:40.838349 18432 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:40.838447 18432 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:40.838479 18432 hybrid_clock.cc:648] HybridClock initialized: now 1786515460838477 us; error 0 us; skew 500 ppm
I20260812 06:17:40.840221 18432 webserver.cc:533] Webserver started at http://127.18.0.62:43983/ using document root <none> and password file <none>
I20260812 06:17:40.840746 18432 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:40.840803 18432 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:40.841005 18432 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:40.842715 18432 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460817553-18432-0/minicluster-data/master-0-root/instance:
uuid: "a67035f46b0540d9a6978dc7e61c670b"
format_stamp: "Formatted at 2026-08-12 06:17:40 on dist-test-slave-vpvm"
I20260812 06:17:40.846346 18432 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.000s	sys 0.003s
I20260812 06:17:40.848692 18450 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:40.849769 18432 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:40.849879 18432 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460817553-18432-0/minicluster-data/master-0-root
uuid: "a67035f46b0540d9a6978dc7e61c670b"
format_stamp: "Formatted at 2026-08-12 06:17:40 on dist-test-slave-vpvm"
I20260812 06:17:40.850013 18432 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460817553-18432-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460817553-18432-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460817553-18432-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:40.865504 18432 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:40.866211 18432 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:17:40.866354 18432 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:40.873776 18537 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.18.0.62:33217 every 8 connection(s)
I20260812 06:17:40.873777 18432 rpc_server.cc:307] RPC server started. Bound to: 127.18.0.62:33217
I20260812 06:17:40.876246 18538 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:40.881750 18538 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a67035f46b0540d9a6978dc7e61c670b: Bootstrap starting.
I20260812 06:17:40.884189 18538 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P a67035f46b0540d9a6978dc7e61c670b: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:40.885119 18538 log.cc:826] T 00000000000000000000000000000000 P a67035f46b0540d9a6978dc7e61c670b: Log is configured to *not* fsync() on all Append() calls
I20260812 06:17:40.886890 18538 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a67035f46b0540d9a6978dc7e61c670b: No bootstrap required, opened a new log
I20260812 06:17:40.889741 18538 raft_consensus.cc:359] T 00000000000000000000000000000000 P a67035f46b0540d9a6978dc7e61c670b [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a67035f46b0540d9a6978dc7e61c670b" member_type: VOTER }
I20260812 06:17:40.889918 18538 raft_consensus.cc:385] T 00000000000000000000000000000000 P a67035f46b0540d9a6978dc7e61c670b [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:40.890012 18538 raft_consensus.cc:740] T 00000000000000000000000000000000 P a67035f46b0540d9a6978dc7e61c670b [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: a67035f46b0540d9a6978dc7e61c670b, State: Initialized, Role: FOLLOWER
I20260812 06:17:40.890691 18538 consensus_queue.cc:260] T 00000000000000000000000000000000 P a67035f46b0540d9a6978dc7e61c670b [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: "a67035f46b0540d9a6978dc7e61c670b" member_type: VOTER }
I20260812 06:17:40.890847 18538 raft_consensus.cc:399] T 00000000000000000000000000000000 P a67035f46b0540d9a6978dc7e61c670b [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:40.890909 18538 raft_consensus.cc:493] T 00000000000000000000000000000000 P a67035f46b0540d9a6978dc7e61c670b [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:40.891043 18538 raft_consensus.cc:3060] T 00000000000000000000000000000000 P a67035f46b0540d9a6978dc7e61c670b [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:40.891872 18538 raft_consensus.cc:515] T 00000000000000000000000000000000 P a67035f46b0540d9a6978dc7e61c670b [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a67035f46b0540d9a6978dc7e61c670b" member_type: VOTER }
I20260812 06:17:40.892333 18538 leader_election.cc:304] T 00000000000000000000000000000000 P a67035f46b0540d9a6978dc7e61c670b [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: a67035f46b0540d9a6978dc7e61c670b; no voters: 
I20260812 06:17:40.892673 18538 leader_election.cc:290] T 00000000000000000000000000000000 P a67035f46b0540d9a6978dc7e61c670b [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:40.892799 18547 raft_consensus.cc:2804] T 00000000000000000000000000000000 P a67035f46b0540d9a6978dc7e61c670b [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:40.893035 18547 raft_consensus.cc:697] T 00000000000000000000000000000000 P a67035f46b0540d9a6978dc7e61c670b [term 1 LEADER]: Becoming Leader. State: Replica: a67035f46b0540d9a6978dc7e61c670b, State: Running, Role: LEADER
I20260812 06:17:40.893455 18547 consensus_queue.cc:237] T 00000000000000000000000000000000 P a67035f46b0540d9a6978dc7e61c670b [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: "a67035f46b0540d9a6978dc7e61c670b" member_type: VOTER }
I20260812 06:17:40.893697 18538 sys_catalog.cc:565] T 00000000000000000000000000000000 P a67035f46b0540d9a6978dc7e61c670b [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:40.895329 18552 sys_catalog.cc:455] T 00000000000000000000000000000000 P a67035f46b0540d9a6978dc7e61c670b [sys.catalog]: SysCatalogTable state changed. Reason: New leader a67035f46b0540d9a6978dc7e61c670b. Latest consensus state: current_term: 1 leader_uuid: "a67035f46b0540d9a6978dc7e61c670b" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a67035f46b0540d9a6978dc7e61c670b" member_type: VOTER } }
I20260812 06:17:40.895371 18550 sys_catalog.cc:455] T 00000000000000000000000000000000 P a67035f46b0540d9a6978dc7e61c670b [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "a67035f46b0540d9a6978dc7e61c670b" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a67035f46b0540d9a6978dc7e61c670b" member_type: VOTER } }
I20260812 06:17:40.895445 18552 sys_catalog.cc:458] T 00000000000000000000000000000000 P a67035f46b0540d9a6978dc7e61c670b [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:40.895481 18550 sys_catalog.cc:458] T 00000000000000000000000000000000 P a67035f46b0540d9a6978dc7e61c670b [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:40.895854 18563 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:40.896008 18432 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:40.898499 18563 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:40.903416 18563 catalog_manager.cc:1383] Generated new cluster ID: 6763f1bd91184902be6aa799500cae7f
I20260812 06:17:40.903494 18563 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:40.920097 18563 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:40.920964 18563 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:40.929896 18563 catalog_manager.cc:6092] T 00000000000000000000000000000000 P a67035f46b0540d9a6978dc7e61c670b: Generated new TSK 0
I20260812 06:17:40.930611 18563 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:40.961230 18432 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:40.964598 18580 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:40.964588 18577 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:40.964701 18432 server_base.cc:1061] running on GCE node
W20260812 06:17:40.964583 18578 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:17:40.965039 18432 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:40.965085 18432 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:40.965106 18432 hybrid_clock.cc:648] HybridClock initialized: now 1786515460965105 us; error 0 us; skew 500 ppm
I20260812 06:17:40.965974 18432 webserver.cc:533] Webserver started at http://127.18.0.1:45085/ using document root <none> and password file <none>
I20260812 06:17:40.966140 18432 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:40.966194 18432 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:40.966274 18432 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:40.966647 18432 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460817553-18432-0/minicluster-data/ts-0-root/instance:
uuid: "f4a61ff324f14ff4a39c263852af208c"
format_stamp: "Formatted at 2026-08-12 06:17:40 on dist-test-slave-vpvm"
I20260812 06:17:40.968101 18432 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:40.969048 18589 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:40.969310 18432 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:40.969379 18432 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460817553-18432-0/minicluster-data/ts-0-root
uuid: "f4a61ff324f14ff4a39c263852af208c"
format_stamp: "Formatted at 2026-08-12 06:17:40 on dist-test-slave-vpvm"
I20260812 06:17:40.969455 18432 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460817553-18432-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460817553-18432-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460817553-18432-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:40.982724 18432 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:40.983201 18432 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:40.983692 18432 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:40.984567 18432 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:40.984619 18432 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:40.984668 18432 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:40.984699 18432 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:40.990823 18432 rpc_server.cc:307] RPC server started. Bound to: 127.18.0.1:46505
I20260812 06:17:40.990978 18701 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.18.0.1:46505 every 8 connection(s)
I20260812 06:17:41.003450 18704 heartbeater.cc:344] Connected to a master server at 127.18.0.62:33217
I20260812 06:17:41.003731 18704 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:41.004168 18704 heartbeater.cc:507] Master 127.18.0.62:33217 requested a full tablet report, sending...
I20260812 06:17:41.005700 18470 ts_manager.cc:194] Registered new tserver with Master: f4a61ff324f14ff4a39c263852af208c (127.18.0.1:46505)
I20260812 06:17:41.005894 18432 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.014468507s
I20260812 06:17:41.007277 18470 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:56884
I20260812 06:17:41.015900 18470 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:56890:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:17:41.030884 18638 tablet_service.cc:1511] Processing CreateTablet for tablet 91669ccc12074f4f82f53423abfc5d2f (DEFAULT_TABLE table=heavy-update-compaction-test [id=487104eab88040a3ad7658c65f92f986]), partition=
I20260812 06:17:41.031329 18638 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 91669ccc12074f4f82f53423abfc5d2f. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:41.033749 18721 tablet_bootstrap.cc:492] T 91669ccc12074f4f82f53423abfc5d2f P f4a61ff324f14ff4a39c263852af208c: Bootstrap starting.
I20260812 06:17:41.035116 18721 tablet_bootstrap.cc:654] T 91669ccc12074f4f82f53423abfc5d2f P f4a61ff324f14ff4a39c263852af208c: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:41.036322 18721 tablet_bootstrap.cc:492] T 91669ccc12074f4f82f53423abfc5d2f P f4a61ff324f14ff4a39c263852af208c: No bootstrap required, opened a new log
I20260812 06:17:41.036419 18721 ts_tablet_manager.cc:1403] T 91669ccc12074f4f82f53423abfc5d2f P f4a61ff324f14ff4a39c263852af208c: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:17:41.036823 18721 raft_consensus.cc:359] T 91669ccc12074f4f82f53423abfc5d2f P f4a61ff324f14ff4a39c263852af208c [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f4a61ff324f14ff4a39c263852af208c" member_type: VOTER last_known_addr { host: "127.18.0.1" port: 46505 } }
I20260812 06:17:41.036926 18721 raft_consensus.cc:385] T 91669ccc12074f4f82f53423abfc5d2f P f4a61ff324f14ff4a39c263852af208c [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:41.036957 18721 raft_consensus.cc:740] T 91669ccc12074f4f82f53423abfc5d2f P f4a61ff324f14ff4a39c263852af208c [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: f4a61ff324f14ff4a39c263852af208c, State: Initialized, Role: FOLLOWER
I20260812 06:17:41.037087 18721 consensus_queue.cc:260] T 91669ccc12074f4f82f53423abfc5d2f P f4a61ff324f14ff4a39c263852af208c [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: "f4a61ff324f14ff4a39c263852af208c" member_type: VOTER last_known_addr { host: "127.18.0.1" port: 46505 } }
I20260812 06:17:41.037173 18721 raft_consensus.cc:399] T 91669ccc12074f4f82f53423abfc5d2f P f4a61ff324f14ff4a39c263852af208c [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:41.037216 18721 raft_consensus.cc:493] T 91669ccc12074f4f82f53423abfc5d2f P f4a61ff324f14ff4a39c263852af208c [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:41.037263 18721 raft_consensus.cc:3060] T 91669ccc12074f4f82f53423abfc5d2f P f4a61ff324f14ff4a39c263852af208c [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:41.037930 18721 raft_consensus.cc:515] T 91669ccc12074f4f82f53423abfc5d2f P f4a61ff324f14ff4a39c263852af208c [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f4a61ff324f14ff4a39c263852af208c" member_type: VOTER last_known_addr { host: "127.18.0.1" port: 46505 } }
I20260812 06:17:41.038092 18721 leader_election.cc:304] T 91669ccc12074f4f82f53423abfc5d2f P f4a61ff324f14ff4a39c263852af208c [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: f4a61ff324f14ff4a39c263852af208c; no voters: 
I20260812 06:17:41.038272 18721 leader_election.cc:290] T 91669ccc12074f4f82f53423abfc5d2f P f4a61ff324f14ff4a39c263852af208c [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:41.038385 18723 raft_consensus.cc:2804] T 91669ccc12074f4f82f53423abfc5d2f P f4a61ff324f14ff4a39c263852af208c [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:41.038614 18721 ts_tablet_manager.cc:1434] T 91669ccc12074f4f82f53423abfc5d2f P f4a61ff324f14ff4a39c263852af208c: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:17:41.038836 18704 heartbeater.cc:499] Master 127.18.0.62:33217 was elected leader, sending a full tablet report...
I20260812 06:17:41.038622 18723 raft_consensus.cc:697] T 91669ccc12074f4f82f53423abfc5d2f P f4a61ff324f14ff4a39c263852af208c [term 1 LEADER]: Becoming Leader. State: Replica: f4a61ff324f14ff4a39c263852af208c, State: Running, Role: LEADER
I20260812 06:17:41.039183 18723 consensus_queue.cc:237] T 91669ccc12074f4f82f53423abfc5d2f P f4a61ff324f14ff4a39c263852af208c [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: "f4a61ff324f14ff4a39c263852af208c" member_type: VOTER last_known_addr { host: "127.18.0.1" port: 46505 } }
I20260812 06:17:41.041751 18470 catalog_manager.cc:5719] T 91669ccc12074f4f82f53423abfc5d2f P f4a61ff324f14ff4a39c263852af208c reported cstate change: term changed from 0 to 1, leader changed from <none> to f4a61ff324f14ff4a39c263852af208c (127.18.0.1). New cstate: current_term: 1 leader_uuid: "f4a61ff324f14ff4a39c263852af208c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f4a61ff324f14ff4a39c263852af208c" member_type: VOTER last_known_addr { host: "127.18.0.1" port: 46505 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:41.106572 18432 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.059s	user 0.020s	sys 0.009s
I20260812 06:17:41.241990 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling FlushMRSOp(91669ccc12074f4f82f53423abfc5d2f): perf score=19.054940
I20260812 06:17:41.423630 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: FlushMRSOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.181s	user 0.134s	sys 0.041s Metrics: {"bytes_written":13907427,"cfile_init":1,"compiler_manager_pool.queue_time_us":280,"delete_count":0,"dirs.queue_time_us":1244,"dirs.run_cpu_time_us":245,"dirs.run_wall_time_us":918,"drs_written":1,"lbm_read_time_us":74,"lbm_reads_lt_1ms":4,"lbm_write_time_us":43097,"lbm_writes_lt_1ms":796,"mutex_wait_us":965,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":225920,"thread_start_us":122,"threads_started":1,"update_count":1695}
I20260812 06:17:41.424625 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling UndoDeltaBlockGCOp(91669ccc12074f4f82f53423abfc5d2f): 16411396 bytes on disk
I20260812 06:17:41.425119 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: UndoDeltaBlockGCOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":45,"lbm_reads_lt_1ms":4}
I20260812 06:17:41.425477 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f): perf score=2.188937
I20260812 06:17:41.438416 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.013s	user 0.001s	sys 0.008s Metrics: {"bytes_written":3856513,"delete_count":0,"lbm_write_time_us":3305,"lbm_writes_lt_1ms":97,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":470}
I20260812 06:17:41.438920 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling LogGCOp(91669ccc12074f4f82f53423abfc5d2f): free 20743880 bytes of WAL
I20260812 06:17:41.439260 18598 log_reader.cc:385] T 91669ccc12074f4f82f53423abfc5d2f: removed 2 log segments from log reader
I20260812 06:17:41.439359 18598 log.cc:1079] T 91669ccc12074f4f82f53423abfc5d2f P f4a61ff324f14ff4a39c263852af208c: Deleting log segment in path: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460817553-18432-0/minicluster-data/ts-0-root/wals/91669ccc12074f4f82f53423abfc5d2f/wal-000000001 (ops 1-6)
I20260812 06:17:41.439456 18598 log.cc:1079] T 91669ccc12074f4f82f53423abfc5d2f P f4a61ff324f14ff4a39c263852af208c: Deleting log segment in path: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460817553-18432-0/minicluster-data/ts-0-root/wals/91669ccc12074f4f82f53423abfc5d2f/wal-000000002 (ops 7-11)
I20260812 06:17:41.444280 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: LogGCOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.005s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:17:41.444650 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f): perf score=1.196750
I20260812 06:17:41.454330 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":2748830,"delete_count":0,"lbm_write_time_us":3192,"lbm_writes_lt_1ms":70,"reinsert_count":0,"update_count":335}
I20260812 06:17:41.454764 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling MajorDeltaCompactionOp(91669ccc12074f4f82f53423abfc5d2f): perf score=1.000000
I20260812 06:17:41.612696 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: MajorDeltaCompactionOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.158s	user 0.122s	sys 0.036s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774770,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":867,"lbm_read_time_us":11849,"lbm_reads_lt_1ms":569,"lbm_write_time_us":24072,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"thread_start_us":304,"threads_started":5,"update_count":2500}
I20260812 06:17:41.613202 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f): perf score=10.126437
I20260812 06:17:41.661540 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.048s	user 0.015s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16146,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:41.662084 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f): perf score=2.188937
I20260812 06:17:41.673648 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3950,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:41.674201 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling MajorDeltaCompactionOp(91669ccc12074f4f82f53423abfc5d2f): perf score=1.000000
I20260812 06:17:41.807217 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: MajorDeltaCompactionOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.133s	user 0.111s	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":691,"lbm_read_time_us":10708,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23384,"lbm_writes_lt_1ms":443,"mutex_wait_us":337,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8320,"update_count":2000}
I20260812 06:17:41.807844 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f): perf score=10.126437
I20260812 06:17:41.846088 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.038s	user 0.022s	sys 0.007s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":12366,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:41.846561 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f): perf score=2.188937
I20260812 06:17:41.856803 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3626,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:41.857384 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling MajorDeltaCompactionOp(91669ccc12074f4f82f53423abfc5d2f): perf score=1.000000
I20260812 06:17:41.984294 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: MajorDeltaCompactionOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.127s	user 0.103s	sys 0.020s 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":892,"lbm_read_time_us":7658,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23947,"lbm_writes_lt_1ms":443,"mutex_wait_us":279,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:17:41.984819 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f): perf score=10.126437
I20260812 06:17:42.024408 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.039s	user 0.011s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16058,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:42.025000 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f): perf score=2.188937
I20260812 06:17:42.035223 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3623,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:42.035965 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling MajorDeltaCompactionOp(91669ccc12074f4f82f53423abfc5d2f): perf score=1.000000
I20260812 06:17:42.151782 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: MajorDeltaCompactionOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.116s	user 0.099s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":127,"lbm_read_time_us":7047,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21420,"lbm_writes_lt_1ms":443,"mutex_wait_us":29,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":118784,"update_count":2000}
I20260812 06:17:42.152359 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f): perf score=10.126437
I20260812 06:17:42.196058 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.044s	user 0.025s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13519,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:42.196606 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f): perf score=2.188937
I20260812 06:17:42.207026 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3861,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:42.207494 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling MajorDeltaCompactionOp(91669ccc12074f4f82f53423abfc5d2f): perf score=1.000000
I20260812 06:17:42.354453 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: MajorDeltaCompactionOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.147s	user 0.118s	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":98,"lbm_read_time_us":9892,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23141,"lbm_writes_lt_1ms":443,"mutex_wait_us":41,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1536,"update_count":2000}
I20260812 06:17:42.355052 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f): perf score=10.126437
I20260812 06:17:42.406144 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.051s	user 0.028s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17271,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:42.406656 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f): perf score=2.188937
I20260812 06:17:42.417130 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3717,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:42.417748 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling MajorDeltaCompactionOp(91669ccc12074f4f82f53423abfc5d2f): perf score=1.000000
I20260812 06:17:42.534727 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: MajorDeltaCompactionOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.117s	user 0.088s	sys 0.028s 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":195,"lbm_read_time_us":7867,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22005,"lbm_writes_lt_1ms":443,"mutex_wait_us":67,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:17:42.535213 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f): perf score=10.126437
I20260812 06:17:42.574002 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.039s	user 0.024s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13379,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:42.574581 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f): perf score=2.188937
I20260812 06:17:42.585314 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3751,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:42.585829 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling FlushMRSOp(91669ccc12074f4f82f53423abfc5d2f): perf score=1.000000
I20260812 06:17:42.615219 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: FlushMRSOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.029s	user 0.026s	sys 0.001s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":65,"dirs.run_cpu_time_us":226,"dirs.run_wall_time_us":1468,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1381,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:42.616086 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling LogGCOp(91669ccc12074f4f82f53423abfc5d2f): free 112239334 bytes of WAL
I20260812 06:17:42.616333 18598 log_reader.cc:385] T 91669ccc12074f4f82f53423abfc5d2f: removed 11 log segments from log reader
I20260812 06:17:42.616395 18598 log.cc:1079] T 91669ccc12074f4f82f53423abfc5d2f P f4a61ff324f14ff4a39c263852af208c: Deleting log segment in path: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460817553-18432-0/minicluster-data/ts-0-root/wals/91669ccc12074f4f82f53423abfc5d2f/wal-000000003 (ops 12-16)
I20260812 06:17:42.616438 18598 log.cc:1079] T 91669ccc12074f4f82f53423abfc5d2f P f4a61ff324f14ff4a39c263852af208c: Deleting log segment in path: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460817553-18432-0/minicluster-data/ts-0-root/wals/91669ccc12074f4f82f53423abfc5d2f/wal-000000004 (ops 17-21)
I20260812 06:17:42.616462 18598 log.cc:1079] T 91669ccc12074f4f82f53423abfc5d2f P f4a61ff324f14ff4a39c263852af208c: Deleting log segment in path: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460817553-18432-0/minicluster-data/ts-0-root/wals/91669ccc12074f4f82f53423abfc5d2f/wal-000000005 (ops 22-26)
I20260812 06:17:42.616492 18598 log.cc:1079] T 91669ccc12074f4f82f53423abfc5d2f P f4a61ff324f14ff4a39c263852af208c: Deleting log segment in path: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460817553-18432-0/minicluster-data/ts-0-root/wals/91669ccc12074f4f82f53423abfc5d2f/wal-000000006 (ops 27-31)
I20260812 06:17:42.616521 18598 log.cc:1079] T 91669ccc12074f4f82f53423abfc5d2f P f4a61ff324f14ff4a39c263852af208c: Deleting log segment in path: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460817553-18432-0/minicluster-data/ts-0-root/wals/91669ccc12074f4f82f53423abfc5d2f/wal-000000007 (ops 32-36)
I20260812 06:17:42.616554 18598 log.cc:1079] T 91669ccc12074f4f82f53423abfc5d2f P f4a61ff324f14ff4a39c263852af208c: Deleting log segment in path: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460817553-18432-0/minicluster-data/ts-0-root/wals/91669ccc12074f4f82f53423abfc5d2f/wal-000000008 (ops 37-41)
I20260812 06:17:42.616585 18598 log.cc:1079] T 91669ccc12074f4f82f53423abfc5d2f P f4a61ff324f14ff4a39c263852af208c: Deleting log segment in path: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460817553-18432-0/minicluster-data/ts-0-root/wals/91669ccc12074f4f82f53423abfc5d2f/wal-000000009 (ops 42-46)
I20260812 06:17:42.616614 18598 log.cc:1079] T 91669ccc12074f4f82f53423abfc5d2f P f4a61ff324f14ff4a39c263852af208c: Deleting log segment in path: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460817553-18432-0/minicluster-data/ts-0-root/wals/91669ccc12074f4f82f53423abfc5d2f/wal-000000010 (ops 47-50)
I20260812 06:17:42.616640 18598 log.cc:1079] T 91669ccc12074f4f82f53423abfc5d2f P f4a61ff324f14ff4a39c263852af208c: Deleting log segment in path: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460817553-18432-0/minicluster-data/ts-0-root/wals/91669ccc12074f4f82f53423abfc5d2f/wal-000000011 (ops 51-55)
I20260812 06:17:42.616665 18598 log.cc:1079] T 91669ccc12074f4f82f53423abfc5d2f P f4a61ff324f14ff4a39c263852af208c: Deleting log segment in path: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460817553-18432-0/minicluster-data/ts-0-root/wals/91669ccc12074f4f82f53423abfc5d2f/wal-000000012 (ops 56-60)
I20260812 06:17:42.616696 18598 log.cc:1079] T 91669ccc12074f4f82f53423abfc5d2f P f4a61ff324f14ff4a39c263852af208c: Deleting log segment in path: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460817553-18432-0/minicluster-data/ts-0-root/wals/91669ccc12074f4f82f53423abfc5d2f/wal-000000013 (ops 61-65)
I20260812 06:17:42.640203 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: LogGCOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.024s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:17:42.640588 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f): perf score=3.181125
I20260812 06:17:42.658710 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.018s	user 0.002s	sys 0.009s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4341,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:42.659152 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f): perf score=2.188937
I20260812 06:17:42.668529 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.009s	user 0.000s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3419,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:42.668995 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling MajorDeltaCompactionOp(91669ccc12074f4f82f53423abfc5d2f): perf score=1.000000
I20260812 06:17:42.828238 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: MajorDeltaCompactionOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.159s	user 0.114s	sys 0.045s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877329,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":480,"lbm_read_time_us":11185,"lbm_reads_lt_1ms":674,"lbm_write_time_us":30709,"lbm_writes_lt_1ms":643,"mutex_wait_us":78,"peak_mem_usage":75542472,"reinsert_count":0,"thread_start_us":70,"threads_started":1,"update_count":3000}
I20260812 06:17:42.829211 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling UndoDeltaBlockGCOp(91669ccc12074f4f82f53423abfc5d2f): 462 bytes on disk
I20260812 06:17:42.829689 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: UndoDeltaBlockGCOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4}
I20260812 06:17:42.831468 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f): perf score=11.118625
I20260812 06:17:42.865434 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.034s	user 0.010s	sys 0.020s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":13447,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:42.866106 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f): perf score=2.188937
I20260812 06:17:42.881656 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5707,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:42.882156 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling MajorDeltaCompactionOp(91669ccc12074f4f82f53423abfc5d2f): perf score=1.000000
I20260812 06:17:42.997920 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: MajorDeltaCompactionOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.116s	user 0.102s	sys 0.008s 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":655,"lbm_read_time_us":6976,"lbm_reads_lt_1ms":464,"lbm_write_time_us":21144,"lbm_writes_lt_1ms":443,"mutex_wait_us":276,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:42.998441 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f): perf score=11.118625
I20260812 06:17:43.041708 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.043s	user 0.011s	sys 0.031s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":18663,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:43.043125 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f): perf score=2.188937
I20260812 06:17:43.058005 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.015s	user 0.007s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4507,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:43.058504 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling MajorDeltaCompactionOp(91669ccc12074f4f82f53423abfc5d2f): perf score=1.000000
I20260812 06:17:43.190737 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: MajorDeltaCompactionOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.132s	user 0.090s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":554,"lbm_read_time_us":8801,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23552,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:43.191334 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f): perf score=11.118625
I20260812 06:17:43.219322 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.028s	user 0.022s	sys 0.004s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":12079,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:43.219863 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f): perf score=2.188937
I20260812 06:17:43.230544 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.010s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3356,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:43.231263 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling MajorDeltaCompactionOp(91669ccc12074f4f82f53423abfc5d2f): perf score=1.000000
I20260812 06:17:43.347141 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: MajorDeltaCompactionOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.116s	user 0.070s	sys 0.045s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672270,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":678,"lbm_read_time_us":7748,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20895,"lbm_writes_lt_1ms":443,"mutex_wait_us":68,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:43.347648 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f): perf score=10.126437
I20260812 06:17:43.395498 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.048s	user 0.018s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15022,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:43.396112 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f): perf score=2.188937
I20260812 06:17:43.406757 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3608,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:43.407332 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling MajorDeltaCompactionOp(91669ccc12074f4f82f53423abfc5d2f): perf score=1.000000
I20260812 06:17:43.530071 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: MajorDeltaCompactionOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.123s	user 0.091s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":248,"lbm_read_time_us":7012,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23200,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:17:43.530611 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f): perf score=10.126437
I20260812 06:17:43.571156 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.039s	user 0.025s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14251,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:43.571678 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f): perf score=2.188937
I20260812 06:17:43.582871 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4175,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:43.583513 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling MajorDeltaCompactionOp(91669ccc12074f4f82f53423abfc5d2f): perf score=1.000000
I20260812 06:17:43.700634 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: MajorDeltaCompactionOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.117s	user 0.089s	sys 0.028s 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":329,"lbm_read_time_us":7571,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22695,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":2000}
I20260812 06:17:43.701273 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f): perf score=10.126437
I20260812 06:17:43.743188 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.042s	user 0.017s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12752,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:43.743887 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f): perf score=2.188937
I20260812 06:17:43.759660 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.016s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5892,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:43.760170 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling MajorDeltaCompactionOp(91669ccc12074f4f82f53423abfc5d2f): perf score=1.000000
I20260812 06:17:43.893693 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: MajorDeltaCompactionOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.133s	user 0.105s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1409,"lbm_read_time_us":10300,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21463,"lbm_writes_lt_1ms":443,"mutex_wait_us":363,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14592,"update_count":2000}
I20260812 06:17:43.894246 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f): perf score=10.126437
I20260812 06:17:43.932346 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.038s	user 0.007s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13690,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:43.932885 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f): perf score=2.188937
I20260812 06:17:43.943329 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.010s	user 0.008s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3691,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:43.943917 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling FlushMRSOp(91669ccc12074f4f82f53423abfc5d2f): perf score=1.000000
I20260812 06:17:43.976040 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: FlushMRSOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.032s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":63,"dirs.run_cpu_time_us":236,"dirs.run_wall_time_us":1320,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1342,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:17:43.976786 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling LogGCOp(91669ccc12074f4f82f53423abfc5d2f): free 133024368 bytes of WAL
I20260812 06:17:43.977025 18598 log_reader.cc:385] T 91669ccc12074f4f82f53423abfc5d2f: removed 13 log segments from log reader
I20260812 06:17:43.977072 18598 log.cc:1079] T 91669ccc12074f4f82f53423abfc5d2f P f4a61ff324f14ff4a39c263852af208c: Deleting log segment in path: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460817553-18432-0/minicluster-data/ts-0-root/wals/91669ccc12074f4f82f53423abfc5d2f/wal-000000014 (ops 66-70)
I20260812 06:17:43.977100 18598 log.cc:1079] T 91669ccc12074f4f82f53423abfc5d2f P f4a61ff324f14ff4a39c263852af208c: Deleting log segment in path: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460817553-18432-0/minicluster-data/ts-0-root/wals/91669ccc12074f4f82f53423abfc5d2f/wal-000000015 (ops 71-74)
I20260812 06:17:43.977128 18598 log.cc:1079] T 91669ccc12074f4f82f53423abfc5d2f P f4a61ff324f14ff4a39c263852af208c: Deleting log segment in path: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460817553-18432-0/minicluster-data/ts-0-root/wals/91669ccc12074f4f82f53423abfc5d2f/wal-000000016 (ops 75-79)
I20260812 06:17:43.977156 18598 log.cc:1079] T 91669ccc12074f4f82f53423abfc5d2f P f4a61ff324f14ff4a39c263852af208c: Deleting log segment in path: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460817553-18432-0/minicluster-data/ts-0-root/wals/91669ccc12074f4f82f53423abfc5d2f/wal-000000017 (ops 80-84)
I20260812 06:17:43.977187 18598 log.cc:1079] T 91669ccc12074f4f82f53423abfc5d2f P f4a61ff324f14ff4a39c263852af208c: Deleting log segment in path: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460817553-18432-0/minicluster-data/ts-0-root/wals/91669ccc12074f4f82f53423abfc5d2f/wal-000000018 (ops 85-89)
I20260812 06:17:43.977222 18598 log.cc:1079] T 91669ccc12074f4f82f53423abfc5d2f P f4a61ff324f14ff4a39c263852af208c: Deleting log segment in path: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460817553-18432-0/minicluster-data/ts-0-root/wals/91669ccc12074f4f82f53423abfc5d2f/wal-000000019 (ops 90-94)
I20260812 06:17:43.977255 18598 log.cc:1079] T 91669ccc12074f4f82f53423abfc5d2f P f4a61ff324f14ff4a39c263852af208c: Deleting log segment in path: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460817553-18432-0/minicluster-data/ts-0-root/wals/91669ccc12074f4f82f53423abfc5d2f/wal-000000020 (ops 95-99)
I20260812 06:17:43.977275 18598 log.cc:1079] T 91669ccc12074f4f82f53423abfc5d2f P f4a61ff324f14ff4a39c263852af208c: Deleting log segment in path: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460817553-18432-0/minicluster-data/ts-0-root/wals/91669ccc12074f4f82f53423abfc5d2f/wal-000000021 (ops 100-104)
I20260812 06:17:43.977308 18598 log.cc:1079] T 91669ccc12074f4f82f53423abfc5d2f P f4a61ff324f14ff4a39c263852af208c: Deleting log segment in path: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460817553-18432-0/minicluster-data/ts-0-root/wals/91669ccc12074f4f82f53423abfc5d2f/wal-000000022 (ops 105-109)
I20260812 06:17:43.977342 18598 log.cc:1079] T 91669ccc12074f4f82f53423abfc5d2f P f4a61ff324f14ff4a39c263852af208c: Deleting log segment in path: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460817553-18432-0/minicluster-data/ts-0-root/wals/91669ccc12074f4f82f53423abfc5d2f/wal-000000023 (ops 110-114)
I20260812 06:17:43.977375 18598 log.cc:1079] T 91669ccc12074f4f82f53423abfc5d2f P f4a61ff324f14ff4a39c263852af208c: Deleting log segment in path: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460817553-18432-0/minicluster-data/ts-0-root/wals/91669ccc12074f4f82f53423abfc5d2f/wal-000000024 (ops 115-119)
I20260812 06:17:43.977408 18598 log.cc:1079] T 91669ccc12074f4f82f53423abfc5d2f P f4a61ff324f14ff4a39c263852af208c: Deleting log segment in path: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460817553-18432-0/minicluster-data/ts-0-root/wals/91669ccc12074f4f82f53423abfc5d2f/wal-000000025 (ops 120-124)
I20260812 06:17:43.977440 18598 log.cc:1079] T 91669ccc12074f4f82f53423abfc5d2f P f4a61ff324f14ff4a39c263852af208c: Deleting log segment in path: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460817553-18432-0/minicluster-data/ts-0-root/wals/91669ccc12074f4f82f53423abfc5d2f/wal-000000026 (ops 125-129)
I20260812 06:17:44.000847 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: LogGCOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.024s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:17:44.001297 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f): perf score=3.181125
I20260812 06:17:44.021258 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.020s	user 0.008s	sys 0.007s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":4252,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:44.021788 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f): perf score=2.188937
I20260812 06:17:44.036442 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.014s	user 0.003s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5394,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:44.036988 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling MajorDeltaCompactionOp(91669ccc12074f4f82f53423abfc5d2f): perf score=1.000000
I20260812 06:17:44.231657 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: MajorDeltaCompactionOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.194s	user 0.146s	sys 0.038s 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":512,"lbm_read_time_us":13090,"lbm_reads_lt_1ms":674,"lbm_write_time_us":30518,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":90,"threads_started":1,"update_count":3000}
I20260812 06:17:44.232282 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f): perf score=14.095187
I20260812 06:17:44.299014 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.065s	user 0.033s	sys 0.020s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":19645,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:44.299702 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling UndoDeltaBlockGCOp(91669ccc12074f4f82f53423abfc5d2f): 472 bytes on disk
I20260812 06:17:44.300184 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: UndoDeltaBlockGCOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4}
I20260812 06:17:44.300844 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f): perf score=2.188937
I20260812 06:17:44.311419 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3851,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:44.311908 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling MajorDeltaCompactionOp(91669ccc12074f4f82f53423abfc5d2f): perf score=1.000000
I20260812 06:17:44.474004 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: MajorDeltaCompactionOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.162s	user 0.122s	sys 0.039s 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":894,"lbm_read_time_us":11093,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27764,"lbm_writes_lt_1ms":543,"mutex_wait_us":256,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":55552,"update_count":2500}
I20260812 06:17:44.474553 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f): perf score=10.126437
I20260812 06:17:44.522820 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.048s	user 0.035s	sys 0.012s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":23070,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:17:44.523459 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f): perf score=2.188937
I20260812 06:17:44.548411 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.025s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4810,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:44.548916 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f): perf score=2.188937
I20260812 06:17:44.567028 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.018s	user 0.006s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3568,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:44.567631 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling MajorDeltaCompactionOp(91669ccc12074f4f82f53423abfc5d2f): perf score=1.000000
I20260812 06:17:44.743733 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: MajorDeltaCompactionOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.176s	user 0.134s	sys 0.040s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774809,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":494,"lbm_read_time_us":13582,"lbm_reads_lt_1ms":573,"lbm_write_time_us":27449,"lbm_writes_lt_1ms":543,"mutex_wait_us":91,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4736,"update_count":2500}
I20260812 06:17:44.744374 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f): perf score=11.118625
I20260812 06:17:44.787061 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.043s	user 0.014s	sys 0.027s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":15175,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:44.787600 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f): perf score=2.188937
I20260812 06:17:44.808800 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.021s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5782,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:44.809355 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f): perf score=2.188937
I20260812 06:17:44.824152 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.015s	user 0.007s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5646,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":92,"reinsert_count":0,"update_count":450}
I20260812 06:17:44.824733 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling MajorDeltaCompactionOp(91669ccc12074f4f82f53423abfc5d2f): perf score=1.000000
I20260812 06:17:44.995158 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: MajorDeltaCompactionOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.170s	user 0.107s	sys 0.052s 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":540,"lbm_read_time_us":9237,"lbm_reads_lt_1ms":573,"lbm_write_time_us":26948,"lbm_writes_lt_1ms":543,"mutex_wait_us":40,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:17:44.995826 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f): perf score=14.095187
I20260812 06:17:45.039966 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.044s	user 0.014s	sys 0.028s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":17736,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:45.040530 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f): perf score=2.188937
I20260812 06:17:45.052845 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.012s	user 0.009s	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:17:45.053428 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling MajorDeltaCompactionOp(91669ccc12074f4f82f53423abfc5d2f): perf score=1.000000
I20260812 06:17:45.196427 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: MajorDeltaCompactionOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.143s	user 0.118s	sys 0.019s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":287,"lbm_read_time_us":8812,"lbm_reads_lt_1ms":568,"lbm_write_time_us":26341,"lbm_writes_lt_1ms":543,"mutex_wait_us":49,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:45.197085 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f): perf score=11.118625
I20260812 06:17:45.227587 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.030s	user 0.025s	sys 0.003s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":12008,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:45.228257 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f): perf score=2.188937
I20260812 06:17:45.239980 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3783,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:45.240486 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling MajorDeltaCompactionOp(91669ccc12074f4f82f53423abfc5d2f): perf score=1.000000
I20260812 06:17:45.364933 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: MajorDeltaCompactionOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.124s	user 0.096s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672269,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":714,"lbm_read_time_us":6848,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24561,"lbm_writes_lt_1ms":443,"mutex_wait_us":288,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:45.365546 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f): perf score=11.118625
I20260812 06:17:45.401566 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.036s	user 0.026s	sys 0.007s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15511,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:45.402105 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f): perf score=2.188937
I20260812 06:17:45.411772 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.010s	user 0.007s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3271,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:45.412415 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling FlushMRSOp(91669ccc12074f4f82f53423abfc5d2f): perf score=1.000000
I20260812 06:17:45.440335 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: FlushMRSOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.028s	user 0.026s	sys 0.000s Metrics: {"bytes_written":1234477,"cfile_init":1,"dirs.queue_time_us":61,"dirs.run_cpu_time_us":224,"dirs.run_wall_time_us":1359,"drs_written":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1445,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:17:45.441126 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling LogGCOp(91669ccc12074f4f82f53423abfc5d2f): free 124710562 bytes of WAL
I20260812 06:17:45.441383 18598 log_reader.cc:385] T 91669ccc12074f4f82f53423abfc5d2f: removed 12 log segments from log reader
I20260812 06:17:45.441433 18598 log.cc:1079] T 91669ccc12074f4f82f53423abfc5d2f P f4a61ff324f14ff4a39c263852af208c: Deleting log segment in path: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460817553-18432-0/minicluster-data/ts-0-root/wals/91669ccc12074f4f82f53423abfc5d2f/wal-000000027 (ops 130-134)
I20260812 06:17:45.441464 18598 log.cc:1079] T 91669ccc12074f4f82f53423abfc5d2f P f4a61ff324f14ff4a39c263852af208c: Deleting log segment in path: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460817553-18432-0/minicluster-data/ts-0-root/wals/91669ccc12074f4f82f53423abfc5d2f/wal-000000028 (ops 135-139)
I20260812 06:17:45.441481 18598 log.cc:1079] T 91669ccc12074f4f82f53423abfc5d2f P f4a61ff324f14ff4a39c263852af208c: Deleting log segment in path: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460817553-18432-0/minicluster-data/ts-0-root/wals/91669ccc12074f4f82f53423abfc5d2f/wal-000000029 (ops 140-144)
I20260812 06:17:45.441509 18598 log.cc:1079] T 91669ccc12074f4f82f53423abfc5d2f P f4a61ff324f14ff4a39c263852af208c: Deleting log segment in path: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460817553-18432-0/minicluster-data/ts-0-root/wals/91669ccc12074f4f82f53423abfc5d2f/wal-000000030 (ops 145-149)
I20260812 06:17:45.441550 18598 log.cc:1079] T 91669ccc12074f4f82f53423abfc5d2f P f4a61ff324f14ff4a39c263852af208c: Deleting log segment in path: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460817553-18432-0/minicluster-data/ts-0-root/wals/91669ccc12074f4f82f53423abfc5d2f/wal-000000031 (ops 150-154)
I20260812 06:17:45.441574 18598 log.cc:1079] T 91669ccc12074f4f82f53423abfc5d2f P f4a61ff324f14ff4a39c263852af208c: Deleting log segment in path: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460817553-18432-0/minicluster-data/ts-0-root/wals/91669ccc12074f4f82f53423abfc5d2f/wal-000000032 (ops 155-159)
I20260812 06:17:45.441605 18598 log.cc:1079] T 91669ccc12074f4f82f53423abfc5d2f P f4a61ff324f14ff4a39c263852af208c: Deleting log segment in path: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460817553-18432-0/minicluster-data/ts-0-root/wals/91669ccc12074f4f82f53423abfc5d2f/wal-000000033 (ops 160-164)
I20260812 06:17:45.441637 18598 log.cc:1079] T 91669ccc12074f4f82f53423abfc5d2f P f4a61ff324f14ff4a39c263852af208c: Deleting log segment in path: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460817553-18432-0/minicluster-data/ts-0-root/wals/91669ccc12074f4f82f53423abfc5d2f/wal-000000034 (ops 165-169)
I20260812 06:17:45.441669 18598 log.cc:1079] T 91669ccc12074f4f82f53423abfc5d2f P f4a61ff324f14ff4a39c263852af208c: Deleting log segment in path: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460817553-18432-0/minicluster-data/ts-0-root/wals/91669ccc12074f4f82f53423abfc5d2f/wal-000000035 (ops 170-174)
I20260812 06:17:45.441701 18598 log.cc:1079] T 91669ccc12074f4f82f53423abfc5d2f P f4a61ff324f14ff4a39c263852af208c: Deleting log segment in path: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460817553-18432-0/minicluster-data/ts-0-root/wals/91669ccc12074f4f82f53423abfc5d2f/wal-000000036 (ops 175-179)
I20260812 06:17:45.441732 18598 log.cc:1079] T 91669ccc12074f4f82f53423abfc5d2f P f4a61ff324f14ff4a39c263852af208c: Deleting log segment in path: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460817553-18432-0/minicluster-data/ts-0-root/wals/91669ccc12074f4f82f53423abfc5d2f/wal-000000037 (ops 180-184)
I20260812 06:17:45.441764 18598 log.cc:1079] T 91669ccc12074f4f82f53423abfc5d2f P f4a61ff324f14ff4a39c263852af208c: Deleting log segment in path: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460817553-18432-0/minicluster-data/ts-0-root/wals/91669ccc12074f4f82f53423abfc5d2f/wal-000000038 (ops 185-189)
I20260812 06:17:45.462182 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: LogGCOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.021s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:17:45.462604 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling UndoDeltaBlockGCOp(91669ccc12074f4f82f53423abfc5d2f): 473 bytes on disk
I20260812 06:17:45.463044 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: UndoDeltaBlockGCOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4}
I20260812 06:17:45.463640 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f): perf score=3.181125
I20260812 06:17:45.484000 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.020s	user 0.011s	sys 0.005s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":7032,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:45.484547 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f): perf score=2.188937
I20260812 06:17:45.499043 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.014s	user 0.010s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5019,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:45.499697 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling MajorDeltaCompactionOp(91669ccc12074f4f82f53423abfc5d2f): perf score=1.000000
I20260812 06:17:45.672415 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: MajorDeltaCompactionOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.172s	user 0.120s	sys 0.043s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877319,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1731,"lbm_read_time_us":19861,"lbm_reads_1-10_ms":1,"lbm_reads_lt_1ms":673,"lbm_write_time_us":29325,"lbm_writes_lt_1ms":643,"mutex_wait_us":852,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1152,"thread_start_us":84,"threads_started":1,"update_count":3000}
I20260812 06:17:45.673018 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f): perf score=14.095187
I20260812 06:17:45.723560 18432 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.617s	user 1.700s	sys 0.116s
I20260812 06:17:45.726657 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.053s	user 0.026s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20521,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:45.727252 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f): perf score=2.188937
I20260812 06:17:45.737577 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: FlushDeltaMemStoresOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4156,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:45.738116 18705 maintenance_manager.cc:419] P f4a61ff324f14ff4a39c263852af208c: Scheduling MajorDeltaCompactionOp(91669ccc12074f4f82f53423abfc5d2f): perf score=1.000000
I20260812 06:17:45.769311 18432 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.045s	user 0.002s	sys 0.000s
I20260812 06:17:45.770149 18432 tablet_server.cc:179] TabletServer@127.18.0.1:0 shutting down...
I20260812 06:17:45.846810 18598 maintenance_manager.cc:643] P f4a61ff324f14ff4a39c263852af208c: MajorDeltaCompactionOp(91669ccc12074f4f82f53423abfc5d2f) complete. Timing: real 0.109s	user 0.084s	sys 0.025s Metrics: {"cfile_cache_hit":396,"cfile_cache_hit_bytes":16204712,"cfile_cache_miss":136,"cfile_cache_miss_bytes":8569975,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":248,"lbm_read_time_us":3476,"lbm_reads_lt_1ms":168,"lbm_write_time_us":23466,"lbm_writes_lt_1ms":543,"mutex_wait_us":40,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12544,"update_count":2500}
I20260812 06:17:45.847590 18432 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:45.848047 18432 tablet_replica.cc:333] T 91669ccc12074f4f82f53423abfc5d2f P f4a61ff324f14ff4a39c263852af208c: stopping tablet replica
I20260812 06:17:45.848300 18432 raft_consensus.cc:2243] T 91669ccc12074f4f82f53423abfc5d2f P f4a61ff324f14ff4a39c263852af208c [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:45.848569 18432 raft_consensus.cc:2272] T 91669ccc12074f4f82f53423abfc5d2f P f4a61ff324f14ff4a39c263852af208c [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:45.864563 18432 tablet_server.cc:196] TabletServer@127.18.0.1:0 shutdown complete.
I20260812 06:17:45.891860 18432 master.cc:562] Master@127.18.0.62:33217 shutting down...
I20260812 06:17:45.895364 18432 raft_consensus.cc:2243] T 00000000000000000000000000000000 P a67035f46b0540d9a6978dc7e61c670b [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:45.895584 18432 raft_consensus.cc:2272] T 00000000000000000000000000000000 P a67035f46b0540d9a6978dc7e61c670b [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:45.895650 18432 tablet_replica.cc:333] T 00000000000000000000000000000000 P a67035f46b0540d9a6978dc7e61c670b: stopping tablet replica
I20260812 06:17:45.907867 18432 master.cc:584] Master@127.18.0.62:33217 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5149 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:17:45.986660 18432 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.18.0.62:45431
I20260812 06:17:45.987087 18432 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:17:45.989094 18432 server_base.cc:1061] running on GCE node
W20260812 06:17:45.989241 18757 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:45.989283 18761 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:45.989271 18758 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:17:45.989605 18432 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:45.989650 18432 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:45.989665 18432 hybrid_clock.cc:648] HybridClock initialized: now 1786515465989664 us; error 0 us; skew 500 ppm
I20260812 06:17:45.990464 18432 webserver.cc:533] Webserver started at http://127.18.0.62:39533/ using document root <none> and password file <none>
I20260812 06:17:45.990649 18432 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:45.990700 18432 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:45.990782 18432 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:45.991160 18432 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460817553-18432-0/minicluster-data/master-0-root/instance:
uuid: "c5e86151b9e247cb855d904a30906476"
format_stamp: "Formatted at 2026-08-12 06:17:45 on dist-test-slave-vpvm"
I20260812 06:17:45.992621 18432 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:45.993654 18767 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:45.993968 18432 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:45.994050 18432 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460817553-18432-0/minicluster-data/master-0-root
uuid: "c5e86151b9e247cb855d904a30906476"
format_stamp: "Formatted at 2026-08-12 06:17:45 on dist-test-slave-vpvm"
I20260812 06:17:45.994140 18432 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460817553-18432-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460817553-18432-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460817553-18432-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:46.002825 18432 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:46.003212 18432 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:46.007541 18432 rpc_server.cc:307] RPC server started. Bound to: 127.18.0.62:45431
I20260812 06:17:46.012596 18864 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.18.0.62:45431 every 8 connection(s)
I20260812 06:17:46.013123 18865 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:46.014995 18865 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P c5e86151b9e247cb855d904a30906476: Bootstrap starting.
I20260812 06:17:46.015805 18865 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P c5e86151b9e247cb855d904a30906476: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:46.016794 18865 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P c5e86151b9e247cb855d904a30906476: No bootstrap required, opened a new log
I20260812 06:17:46.017159 18865 raft_consensus.cc:359] T 00000000000000000000000000000000 P c5e86151b9e247cb855d904a30906476 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c5e86151b9e247cb855d904a30906476" member_type: VOTER }
I20260812 06:17:46.017244 18865 raft_consensus.cc:385] T 00000000000000000000000000000000 P c5e86151b9e247cb855d904a30906476 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:46.017264 18865 raft_consensus.cc:740] T 00000000000000000000000000000000 P c5e86151b9e247cb855d904a30906476 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: c5e86151b9e247cb855d904a30906476, State: Initialized, Role: FOLLOWER
I20260812 06:17:46.017377 18865 consensus_queue.cc:260] T 00000000000000000000000000000000 P c5e86151b9e247cb855d904a30906476 [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: "c5e86151b9e247cb855d904a30906476" member_type: VOTER }
I20260812 06:17:46.017433 18865 raft_consensus.cc:399] T 00000000000000000000000000000000 P c5e86151b9e247cb855d904a30906476 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:46.017454 18865 raft_consensus.cc:493] T 00000000000000000000000000000000 P c5e86151b9e247cb855d904a30906476 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:46.017480 18865 raft_consensus.cc:3060] T 00000000000000000000000000000000 P c5e86151b9e247cb855d904a30906476 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:46.018194 18865 raft_consensus.cc:515] T 00000000000000000000000000000000 P c5e86151b9e247cb855d904a30906476 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c5e86151b9e247cb855d904a30906476" member_type: VOTER }
I20260812 06:17:46.018321 18865 leader_election.cc:304] T 00000000000000000000000000000000 P c5e86151b9e247cb855d904a30906476 [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: c5e86151b9e247cb855d904a30906476; no voters: 
I20260812 06:17:46.018474 18865 leader_election.cc:290] T 00000000000000000000000000000000 P c5e86151b9e247cb855d904a30906476 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:46.018597 18878 raft_consensus.cc:2804] T 00000000000000000000000000000000 P c5e86151b9e247cb855d904a30906476 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:46.018816 18878 raft_consensus.cc:697] T 00000000000000000000000000000000 P c5e86151b9e247cb855d904a30906476 [term 1 LEADER]: Becoming Leader. State: Replica: c5e86151b9e247cb855d904a30906476, State: Running, Role: LEADER
I20260812 06:17:46.018945 18865 sys_catalog.cc:565] T 00000000000000000000000000000000 P c5e86151b9e247cb855d904a30906476 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:46.018966 18878 consensus_queue.cc:237] T 00000000000000000000000000000000 P c5e86151b9e247cb855d904a30906476 [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: "c5e86151b9e247cb855d904a30906476" member_type: VOTER }
I20260812 06:17:46.019419 18879 sys_catalog.cc:455] T 00000000000000000000000000000000 P c5e86151b9e247cb855d904a30906476 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "c5e86151b9e247cb855d904a30906476" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c5e86151b9e247cb855d904a30906476" member_type: VOTER } }
I20260812 06:17:46.019461 18881 sys_catalog.cc:455] T 00000000000000000000000000000000 P c5e86151b9e247cb855d904a30906476 [sys.catalog]: SysCatalogTable state changed. Reason: New leader c5e86151b9e247cb855d904a30906476. Latest consensus state: current_term: 1 leader_uuid: "c5e86151b9e247cb855d904a30906476" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c5e86151b9e247cb855d904a30906476" member_type: VOTER } }
I20260812 06:17:46.019515 18879 sys_catalog.cc:458] T 00000000000000000000000000000000 P c5e86151b9e247cb855d904a30906476 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:46.019546 18881 sys_catalog.cc:458] T 00000000000000000000000000000000 P c5e86151b9e247cb855d904a30906476 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:46.019762 18884 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:46.020556 18884 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:46.020716 18432 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:46.022330 18884 catalog_manager.cc:1383] Generated new cluster ID: af47ffcb3eef4392ad7b62352b98aadd
I20260812 06:17:46.022388 18884 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:46.035358 18884 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:46.035966 18884 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:46.047438 18884 catalog_manager.cc:6092] T 00000000000000000000000000000000 P c5e86151b9e247cb855d904a30906476: Generated new TSK 0
I20260812 06:17:46.047647 18884 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:46.053103 18432 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:46.055117 18903 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:46.055143 18906 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:46.055186 18904 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:17:46.055265 18432 server_base.cc:1061] running on GCE node
I20260812 06:17:46.055550 18432 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:46.055598 18432 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:46.055619 18432 hybrid_clock.cc:648] HybridClock initialized: now 1786515466055619 us; error 0 us; skew 500 ppm
I20260812 06:17:46.056408 18432 webserver.cc:533] Webserver started at http://127.18.0.1:41611/ using document root <none> and password file <none>
I20260812 06:17:46.056567 18432 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:46.056622 18432 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:46.056700 18432 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:46.057101 18432 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460817553-18432-0/minicluster-data/ts-0-root/instance:
uuid: "026c0a7fb56848d3b6553bdf36098dc3"
format_stamp: "Formatted at 2026-08-12 06:17:46 on dist-test-slave-vpvm"
I20260812 06:17:46.058681 18432 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:17:46.059656 18916 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:46.059871 18432 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:46.059952 18432 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460817553-18432-0/minicluster-data/ts-0-root
uuid: "026c0a7fb56848d3b6553bdf36098dc3"
format_stamp: "Formatted at 2026-08-12 06:17:46 on dist-test-slave-vpvm"
I20260812 06:17:46.060024 18432 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460817553-18432-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460817553-18432-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460817553-18432-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:46.065827 18432 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:46.066227 18432 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:46.066530 18432 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:46.066982 18432 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:46.067029 18432 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:46.067075 18432 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:46.067102 18432 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:46.071152 18432 rpc_server.cc:307] RPC server started. Bound to: 127.18.0.1:45345
I20260812 06:17:46.071430 19048 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.18.0.1:45345 every 8 connection(s)
I20260812 06:17:46.079039 19049 heartbeater.cc:344] Connected to a master server at 127.18.0.62:45431
I20260812 06:17:46.079149 19049 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:46.079355 19049 heartbeater.cc:507] Master 127.18.0.62:45431 requested a full tablet report, sending...
I20260812 06:17:46.079994 18796 ts_manager.cc:194] Registered new tserver with Master: 026c0a7fb56848d3b6553bdf36098dc3 (127.18.0.1:45345)
I20260812 06:17:46.080403 18432 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.008748871s
I20260812 06:17:46.080791 18796 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:48532
I20260812 06:17:46.087368 18796 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:48542:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:17:46.096094 18972 tablet_service.cc:1511] Processing CreateTablet for tablet e9c34b620f6243d8abfb5e17a5c5f35a (DEFAULT_TABLE table=heavy-update-compaction-test [id=d758614788c54863aa80494f853e4653]), partition=
I20260812 06:17:46.096374 18972 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet e9c34b620f6243d8abfb5e17a5c5f35a. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:46.098456 19072 tablet_bootstrap.cc:492] T e9c34b620f6243d8abfb5e17a5c5f35a P 026c0a7fb56848d3b6553bdf36098dc3: Bootstrap starting.
I20260812 06:17:46.099354 19072 tablet_bootstrap.cc:654] T e9c34b620f6243d8abfb5e17a5c5f35a P 026c0a7fb56848d3b6553bdf36098dc3: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:46.100440 19072 tablet_bootstrap.cc:492] T e9c34b620f6243d8abfb5e17a5c5f35a P 026c0a7fb56848d3b6553bdf36098dc3: No bootstrap required, opened a new log
I20260812 06:17:46.100549 19072 ts_tablet_manager.cc:1403] T e9c34b620f6243d8abfb5e17a5c5f35a P 026c0a7fb56848d3b6553bdf36098dc3: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:46.100962 19072 raft_consensus.cc:359] T e9c34b620f6243d8abfb5e17a5c5f35a P 026c0a7fb56848d3b6553bdf36098dc3 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "026c0a7fb56848d3b6553bdf36098dc3" member_type: VOTER last_known_addr { host: "127.18.0.1" port: 45345 } }
I20260812 06:17:46.101058 19072 raft_consensus.cc:385] T e9c34b620f6243d8abfb5e17a5c5f35a P 026c0a7fb56848d3b6553bdf36098dc3 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:46.101089 19072 raft_consensus.cc:740] T e9c34b620f6243d8abfb5e17a5c5f35a P 026c0a7fb56848d3b6553bdf36098dc3 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 026c0a7fb56848d3b6553bdf36098dc3, State: Initialized, Role: FOLLOWER
I20260812 06:17:46.101239 19072 consensus_queue.cc:260] T e9c34b620f6243d8abfb5e17a5c5f35a P 026c0a7fb56848d3b6553bdf36098dc3 [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: "026c0a7fb56848d3b6553bdf36098dc3" member_type: VOTER last_known_addr { host: "127.18.0.1" port: 45345 } }
I20260812 06:17:46.101326 19072 raft_consensus.cc:399] T e9c34b620f6243d8abfb5e17a5c5f35a P 026c0a7fb56848d3b6553bdf36098dc3 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:46.101367 19072 raft_consensus.cc:493] T e9c34b620f6243d8abfb5e17a5c5f35a P 026c0a7fb56848d3b6553bdf36098dc3 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:46.101418 19072 raft_consensus.cc:3060] T e9c34b620f6243d8abfb5e17a5c5f35a P 026c0a7fb56848d3b6553bdf36098dc3 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:46.102284 19072 raft_consensus.cc:515] T e9c34b620f6243d8abfb5e17a5c5f35a P 026c0a7fb56848d3b6553bdf36098dc3 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "026c0a7fb56848d3b6553bdf36098dc3" member_type: VOTER last_known_addr { host: "127.18.0.1" port: 45345 } }
I20260812 06:17:46.102408 19072 leader_election.cc:304] T e9c34b620f6243d8abfb5e17a5c5f35a P 026c0a7fb56848d3b6553bdf36098dc3 [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: 026c0a7fb56848d3b6553bdf36098dc3; no voters: 
I20260812 06:17:46.102572 19072 leader_election.cc:290] T e9c34b620f6243d8abfb5e17a5c5f35a P 026c0a7fb56848d3b6553bdf36098dc3 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:46.102682 19075 raft_consensus.cc:2804] T e9c34b620f6243d8abfb5e17a5c5f35a P 026c0a7fb56848d3b6553bdf36098dc3 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:46.102866 19072 ts_tablet_manager.cc:1434] T e9c34b620f6243d8abfb5e17a5c5f35a P 026c0a7fb56848d3b6553bdf36098dc3: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:17:46.102895 19049 heartbeater.cc:499] Master 127.18.0.62:45431 was elected leader, sending a full tablet report...
I20260812 06:17:46.102885 19075 raft_consensus.cc:697] T e9c34b620f6243d8abfb5e17a5c5f35a P 026c0a7fb56848d3b6553bdf36098dc3 [term 1 LEADER]: Becoming Leader. State: Replica: 026c0a7fb56848d3b6553bdf36098dc3, State: Running, Role: LEADER
I20260812 06:17:46.103229 19075 consensus_queue.cc:237] T e9c34b620f6243d8abfb5e17a5c5f35a P 026c0a7fb56848d3b6553bdf36098dc3 [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: "026c0a7fb56848d3b6553bdf36098dc3" member_type: VOTER last_known_addr { host: "127.18.0.1" port: 45345 } }
I20260812 06:17:46.104609 18796 catalog_manager.cc:5719] T e9c34b620f6243d8abfb5e17a5c5f35a P 026c0a7fb56848d3b6553bdf36098dc3 reported cstate change: term changed from 0 to 1, leader changed from <none> to 026c0a7fb56848d3b6553bdf36098dc3 (127.18.0.1). New cstate: current_term: 1 leader_uuid: "026c0a7fb56848d3b6553bdf36098dc3" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "026c0a7fb56848d3b6553bdf36098dc3" member_type: VOTER last_known_addr { host: "127.18.0.1" port: 45345 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:46.164799 18432 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.053s	user 0.010s	sys 0.012s
I20260812 06:17:46.322217 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling FlushMRSOp(e9c34b620f6243d8abfb5e17a5c5f35a): perf score=19.054940
I20260812 06:17:46.467839 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: FlushMRSOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.145s	user 0.107s	sys 0.036s Metrics: {"bytes_written":12307491,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":97,"dirs.run_cpu_time_us":203,"dirs.run_wall_time_us":873,"drs_written":1,"lbm_read_time_us":79,"lbm_reads_lt_1ms":4,"lbm_write_time_us":34808,"lbm_writes_lt_1ms":767,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"spinlock_wait_cycles":1280,"update_count":1500}
I20260812 06:17:46.468531 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling LogGCOp(e9c34b620f6243d8abfb5e17a5c5f35a): free 20743880 bytes of WAL
I20260812 06:17:46.468775 18926 log_reader.cc:385] T e9c34b620f6243d8abfb5e17a5c5f35a: removed 2 log segments from log reader
I20260812 06:17:46.468823 18926 log.cc:1079] T e9c34b620f6243d8abfb5e17a5c5f35a P 026c0a7fb56848d3b6553bdf36098dc3: Deleting log segment in path: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460817553-18432-0/minicluster-data/ts-0-root/wals/e9c34b620f6243d8abfb5e17a5c5f35a/wal-000000001 (ops 1-6)
I20260812 06:17:46.468854 18926 log.cc:1079] T e9c34b620f6243d8abfb5e17a5c5f35a P 026c0a7fb56848d3b6553bdf36098dc3: Deleting log segment in path: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460817553-18432-0/minicluster-data/ts-0-root/wals/e9c34b620f6243d8abfb5e17a5c5f35a/wal-000000002 (ops 7-11)
I20260812 06:17:46.472398 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: LogGCOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.004s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:17:46.472765 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling UndoDeltaBlockGCOp(e9c34b620f6243d8abfb5e17a5c5f35a): 16821648 bytes on disk
I20260812 06:17:46.473208 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: UndoDeltaBlockGCOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4}
I20260812 06:17:46.473665 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a): perf score=2.188937
I20260812 06:17:46.484436 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3913,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:46.484999 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling MajorDeltaCompactionOp(e9c34b620f6243d8abfb5e17a5c5f35a): perf score=1.000000
I20260812 06:17:46.621654 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: MajorDeltaCompactionOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.136s	user 0.097s	sys 0.040s Metrics: {"cfile_cache_miss":422,"cfile_cache_miss_bytes":20303019,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":512,"lbm_read_time_us":9860,"lbm_reads_lt_1ms":458,"lbm_write_time_us":21407,"lbm_writes_lt_1ms":433,"peak_mem_usage":49238594,"reinsert_count":0,"spinlock_wait_cycles":16256,"thread_start_us":325,"threads_started":5,"update_count":1950}
I20260812 06:17:46.622284 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a): perf score=10.126437
I20260812 06:17:46.661628 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.039s	user 0.026s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15621,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:46.662159 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a): perf score=2.188937
I20260812 06:17:46.672217 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3592,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:46.673151 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling MajorDeltaCompactionOp(e9c34b620f6243d8abfb5e17a5c5f35a): perf score=1.000000
I20260812 06:17:46.826372 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: MajorDeltaCompactionOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.153s	user 0.101s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":494,"lbm_read_time_us":8659,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22985,"lbm_writes_lt_1ms":443,"mutex_wait_us":58,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2000}
I20260812 06:17:46.826822 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a): perf score=10.126437
I20260812 06:17:46.866130 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.039s	user 0.012s	sys 0.020s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":13634,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:46.866670 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a): perf score=2.188937
I20260812 06:17:46.877292 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3681,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:46.878080 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling MajorDeltaCompactionOp(e9c34b620f6243d8abfb5e17a5c5f35a): perf score=1.000000
I20260812 06:17:46.997327 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: MajorDeltaCompactionOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.119s	user 0.078s	sys 0.041s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713273,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":801,"lbm_read_time_us":8352,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20953,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7168,"update_count":2000}
I20260812 06:17:46.997874 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a): perf score=10.126437
I20260812 06:17:47.040086 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.042s	user 0.024s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16580,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:47.040609 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a): perf score=2.188937
I20260812 06:17:47.050612 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3619,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:47.051090 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling MajorDeltaCompactionOp(e9c34b620f6243d8abfb5e17a5c5f35a): perf score=1.000000
I20260812 06:17:47.176836 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: MajorDeltaCompactionOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.126s	user 0.090s	sys 0.035s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":624,"lbm_read_time_us":8700,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23391,"lbm_writes_lt_1ms":443,"mutex_wait_us":309,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12928,"update_count":2000}
I20260812 06:17:47.177336 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a): perf score=10.126437
I20260812 06:17:47.226379 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.049s	user 0.031s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13225,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:47.226939 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a): perf score=2.188937
I20260812 06:17:47.237151 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3822,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:47.237588 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling MajorDeltaCompactionOp(e9c34b620f6243d8abfb5e17a5c5f35a): perf score=1.000000
I20260812 06:17:47.377290 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: MajorDeltaCompactionOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.140s	user 0.092s	sys 0.044s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":195,"lbm_read_time_us":10736,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20722,"lbm_writes_lt_1ms":443,"mutex_wait_us":27,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":21632,"update_count":2000}
I20260812 06:17:47.377810 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a): perf score=10.126437
I20260812 06:17:47.420188 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.042s	user 0.024s	sys 0.005s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":12897,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":1500}
I20260812 06:17:47.420761 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a): perf score=2.188937
I20260812 06:17:47.431788 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.011s	user 0.004s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3918,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:47.432497 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling MajorDeltaCompactionOp(e9c34b620f6243d8abfb5e17a5c5f35a): perf score=1.000000
I20260812 06:17:47.544008 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: MajorDeltaCompactionOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.111s	user 0.091s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713274,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":482,"lbm_read_time_us":7419,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21135,"lbm_writes_lt_1ms":443,"mutex_wait_us":263,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":18176,"update_count":2000}
I20260812 06:17:47.544595 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a): perf score=10.126437
I20260812 06:17:47.587574 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.043s	user 0.013s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14548,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:47.588048 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a): perf score=2.188937
I20260812 06:17:47.599865 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4434,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:47.600488 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling MajorDeltaCompactionOp(e9c34b620f6243d8abfb5e17a5c5f35a): perf score=1.000000
I20260812 06:17:47.718779 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: MajorDeltaCompactionOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.118s	user 0.086s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":439,"lbm_read_time_us":8565,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22539,"lbm_writes_lt_1ms":443,"mutex_wait_us":43,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:17:47.719367 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a): perf score=10.126437
I20260812 06:17:47.771854 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.052s	user 0.026s	sys 0.024s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19727,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:47.772476 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a): perf score=2.188937
I20260812 06:17:47.783025 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3850,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:47.783661 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling FlushMRSOp(e9c34b620f6243d8abfb5e17a5c5f35a): perf score=1.000000
I20260812 06:17:47.826047 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: FlushMRSOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.042s	user 0.027s	sys 0.004s Metrics: {"bytes_written":1275444,"cfile_init":1,"dirs.queue_time_us":82,"dirs.run_cpu_time_us":239,"dirs.run_wall_time_us":1351,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1427,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:47.826704 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling LogGCOp(e9c34b620f6243d8abfb5e17a5c5f35a): free 133024360 bytes of WAL
I20260812 06:17:47.826934 18926 log_reader.cc:385] T e9c34b620f6243d8abfb5e17a5c5f35a: removed 13 log segments from log reader
I20260812 06:17:47.826980 18926 log.cc:1079] T e9c34b620f6243d8abfb5e17a5c5f35a P 026c0a7fb56848d3b6553bdf36098dc3: Deleting log segment in path: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460817553-18432-0/minicluster-data/ts-0-root/wals/e9c34b620f6243d8abfb5e17a5c5f35a/wal-000000003 (ops 12-16)
I20260812 06:17:47.827013 18926 log.cc:1079] T e9c34b620f6243d8abfb5e17a5c5f35a P 026c0a7fb56848d3b6553bdf36098dc3: Deleting log segment in path: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460817553-18432-0/minicluster-data/ts-0-root/wals/e9c34b620f6243d8abfb5e17a5c5f35a/wal-000000004 (ops 17-21)
I20260812 06:17:47.827044 18926 log.cc:1079] T e9c34b620f6243d8abfb5e17a5c5f35a P 026c0a7fb56848d3b6553bdf36098dc3: Deleting log segment in path: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460817553-18432-0/minicluster-data/ts-0-root/wals/e9c34b620f6243d8abfb5e17a5c5f35a/wal-000000005 (ops 22-26)
I20260812 06:17:47.827076 18926 log.cc:1079] T e9c34b620f6243d8abfb5e17a5c5f35a P 026c0a7fb56848d3b6553bdf36098dc3: Deleting log segment in path: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460817553-18432-0/minicluster-data/ts-0-root/wals/e9c34b620f6243d8abfb5e17a5c5f35a/wal-000000006 (ops 27-30)
I20260812 06:17:47.827109 18926 log.cc:1079] T e9c34b620f6243d8abfb5e17a5c5f35a P 026c0a7fb56848d3b6553bdf36098dc3: Deleting log segment in path: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460817553-18432-0/minicluster-data/ts-0-root/wals/e9c34b620f6243d8abfb5e17a5c5f35a/wal-000000007 (ops 31-35)
I20260812 06:17:47.827152 18926 log.cc:1079] T e9c34b620f6243d8abfb5e17a5c5f35a P 026c0a7fb56848d3b6553bdf36098dc3: Deleting log segment in path: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460817553-18432-0/minicluster-data/ts-0-root/wals/e9c34b620f6243d8abfb5e17a5c5f35a/wal-000000008 (ops 36-40)
I20260812 06:17:47.827181 18926 log.cc:1079] T e9c34b620f6243d8abfb5e17a5c5f35a P 026c0a7fb56848d3b6553bdf36098dc3: Deleting log segment in path: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460817553-18432-0/minicluster-data/ts-0-root/wals/e9c34b620f6243d8abfb5e17a5c5f35a/wal-000000009 (ops 41-45)
I20260812 06:17:47.827224 18926 log.cc:1079] T e9c34b620f6243d8abfb5e17a5c5f35a P 026c0a7fb56848d3b6553bdf36098dc3: Deleting log segment in path: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460817553-18432-0/minicluster-data/ts-0-root/wals/e9c34b620f6243d8abfb5e17a5c5f35a/wal-000000010 (ops 46-50)
I20260812 06:17:47.827255 18926 log.cc:1079] T e9c34b620f6243d8abfb5e17a5c5f35a P 026c0a7fb56848d3b6553bdf36098dc3: Deleting log segment in path: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460817553-18432-0/minicluster-data/ts-0-root/wals/e9c34b620f6243d8abfb5e17a5c5f35a/wal-000000011 (ops 51-55)
I20260812 06:17:47.827286 18926 log.cc:1079] T e9c34b620f6243d8abfb5e17a5c5f35a P 026c0a7fb56848d3b6553bdf36098dc3: Deleting log segment in path: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460817553-18432-0/minicluster-data/ts-0-root/wals/e9c34b620f6243d8abfb5e17a5c5f35a/wal-000000012 (ops 56-60)
I20260812 06:17:47.827316 18926 log.cc:1079] T e9c34b620f6243d8abfb5e17a5c5f35a P 026c0a7fb56848d3b6553bdf36098dc3: Deleting log segment in path: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460817553-18432-0/minicluster-data/ts-0-root/wals/e9c34b620f6243d8abfb5e17a5c5f35a/wal-000000013 (ops 61-65)
I20260812 06:17:47.827347 18926 log.cc:1079] T e9c34b620f6243d8abfb5e17a5c5f35a P 026c0a7fb56848d3b6553bdf36098dc3: Deleting log segment in path: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460817553-18432-0/minicluster-data/ts-0-root/wals/e9c34b620f6243d8abfb5e17a5c5f35a/wal-000000014 (ops 66-70)
I20260812 06:17:47.827379 18926 log.cc:1079] T e9c34b620f6243d8abfb5e17a5c5f35a P 026c0a7fb56848d3b6553bdf36098dc3: Deleting log segment in path: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460817553-18432-0/minicluster-data/ts-0-root/wals/e9c34b620f6243d8abfb5e17a5c5f35a/wal-000000015 (ops 71-75)
I20260812 06:17:47.850668 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: LogGCOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.024s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:17:47.851091 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling UndoDeltaBlockGCOp(e9c34b620f6243d8abfb5e17a5c5f35a): 482 bytes on disk
I20260812 06:17:47.851727 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: UndoDeltaBlockGCOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":88,"lbm_reads_lt_1ms":4}
I20260812 06:17:47.852276 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a): perf score=3.181125
I20260812 06:17:47.870808 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.018s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4028,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:47.871241 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a): perf score=2.188937
I20260812 06:17:47.880599 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.009s	user 0.004s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3238,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:47.881073 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling MajorDeltaCompactionOp(e9c34b620f6243d8abfb5e17a5c5f35a): perf score=1.000000
I20260812 06:17:48.070022 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: MajorDeltaCompactionOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.189s	user 0.116s	sys 0.072s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918324,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":392,"lbm_read_time_us":15162,"lbm_reads_lt_1ms":674,"lbm_write_time_us":26975,"lbm_writes_lt_1ms":643,"mutex_wait_us":39,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":15616,"thread_start_us":78,"threads_started":1,"update_count":3000}
I20260812 06:17:48.072755 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a): perf score=14.095187
I20260812 06:17:48.116415 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.043s	user 0.028s	sys 0.011s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17684,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:48.117106 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling MajorDeltaCompactionOp(e9c34b620f6243d8abfb5e17a5c5f35a): perf score=1.000000
I20260812 06:17:48.258601 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: MajorDeltaCompactionOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.141s	user 0.110s	sys 0.029s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713152,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":470,"lbm_read_time_us":10175,"lbm_reads_lt_1ms":463,"lbm_write_time_us":23450,"lbm_writes_lt_1ms":443,"mutex_wait_us":44,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6016,"update_count":2000}
I20260812 06:17:48.261152 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a): perf score=11.118625
I20260812 06:17:48.296691 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.035s	user 0.020s	sys 0.012s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":15044,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:48.297160 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a): perf score=2.188937
I20260812 06:17:48.321673 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.024s	user 0.004s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4471,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:48.322237 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a): perf score=2.188937
I20260812 06:17:48.333168 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3959,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:48.333741 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling MajorDeltaCompactionOp(e9c34b620f6243d8abfb5e17a5c5f35a): perf score=1.000000
I20260812 06:17:48.511044 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: MajorDeltaCompactionOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.177s	user 0.103s	sys 0.060s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815795,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":226,"lbm_read_time_us":10523,"lbm_reads_lt_1ms":573,"lbm_write_time_us":24564,"lbm_writes_lt_1ms":543,"mutex_wait_us":2,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2500}
I20260812 06:17:48.511596 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a): perf score=14.095187
I20260812 06:17:48.562211 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.050s	user 0.032s	sys 0.013s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19504,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:48.562692 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a): perf score=2.188937
I20260812 06:17:48.574188 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.011s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4098,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:48.574702 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling MajorDeltaCompactionOp(e9c34b620f6243d8abfb5e17a5c5f35a): perf score=1.000000
I20260812 06:17:48.726613 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: MajorDeltaCompactionOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.152s	user 0.125s	sys 0.024s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":131,"lbm_read_time_us":10493,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26805,"lbm_writes_lt_1ms":543,"mutex_wait_us":34,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13568,"update_count":2500}
I20260812 06:17:48.727090 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a): perf score=11.118625
I20260812 06:17:48.757511 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.030s	user 0.018s	sys 0.008s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":12349,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:48.758023 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a): perf score=2.188937
I20260812 06:17:48.782399 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.024s	user 0.011s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4538,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:48.782956 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a): perf score=2.188937
I20260812 06:17:48.793514 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.010s	user 0.005s	sys 0.004s 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:17:48.794147 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling MajorDeltaCompactionOp(e9c34b620f6243d8abfb5e17a5c5f35a): perf score=1.000000
I20260812 06:17:48.944765 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: MajorDeltaCompactionOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.150s	user 0.119s	sys 0.025s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815794,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":556,"lbm_read_time_us":9319,"lbm_reads_lt_1ms":573,"lbm_write_time_us":28744,"lbm_writes_lt_1ms":543,"mutex_wait_us":56,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":21888,"update_count":2500}
I20260812 06:17:48.945297 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a): perf score=11.118625
I20260812 06:17:48.974278 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.029s	user 0.016s	sys 0.012s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":11561,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:48.975051 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a): perf score=2.188937
I20260812 06:17:48.988204 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.013s	user 0.006s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4473,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:48.988766 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling MajorDeltaCompactionOp(e9c34b620f6243d8abfb5e17a5c5f35a): perf score=1.000000
I20260812 06:17:49.110105 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: MajorDeltaCompactionOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.121s	user 0.103s	sys 0.018s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713263,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":313,"lbm_read_time_us":8576,"lbm_reads_lt_1ms":464,"lbm_write_time_us":22803,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12928,"update_count":2000}
I20260812 06:17:49.110785 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a): perf score=10.126437
I20260812 06:17:49.155752 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.045s	user 0.025s	sys 0.009s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":14984,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:49.156306 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a): perf score=2.188937
I20260812 06:17:49.171785 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.015s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5603,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:49.172463 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling FlushMRSOp(e9c34b620f6243d8abfb5e17a5c5f35a): perf score=1.000000
I20260812 06:17:49.198938 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: FlushMRSOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.026s	user 0.021s	sys 0.004s Metrics: {"bytes_written":1193507,"cfile_init":1,"dirs.queue_time_us":50,"dirs.run_cpu_time_us":282,"dirs.run_wall_time_us":1267,"drs_written":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1604,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:49.199712 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling LogGCOp(e9c34b620f6243d8abfb5e17a5c5f35a): free 120553402 bytes of WAL
I20260812 06:17:49.199956 18926 log_reader.cc:385] T e9c34b620f6243d8abfb5e17a5c5f35a: removed 12 log segments from log reader
I20260812 06:17:49.200019 18926 log.cc:1079] T e9c34b620f6243d8abfb5e17a5c5f35a P 026c0a7fb56848d3b6553bdf36098dc3: Deleting log segment in path: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460817553-18432-0/minicluster-data/ts-0-root/wals/e9c34b620f6243d8abfb5e17a5c5f35a/wal-000000016 (ops 76-80)
I20260812 06:17:49.200060 18926 log.cc:1079] T e9c34b620f6243d8abfb5e17a5c5f35a P 026c0a7fb56848d3b6553bdf36098dc3: Deleting log segment in path: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460817553-18432-0/minicluster-data/ts-0-root/wals/e9c34b620f6243d8abfb5e17a5c5f35a/wal-000000017 (ops 81-85)
I20260812 06:17:49.200094 18926 log.cc:1079] T e9c34b620f6243d8abfb5e17a5c5f35a P 026c0a7fb56848d3b6553bdf36098dc3: Deleting log segment in path: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460817553-18432-0/minicluster-data/ts-0-root/wals/e9c34b620f6243d8abfb5e17a5c5f35a/wal-000000018 (ops 86-90)
I20260812 06:17:49.200120 18926 log.cc:1079] T e9c34b620f6243d8abfb5e17a5c5f35a P 026c0a7fb56848d3b6553bdf36098dc3: Deleting log segment in path: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460817553-18432-0/minicluster-data/ts-0-root/wals/e9c34b620f6243d8abfb5e17a5c5f35a/wal-000000019 (ops 91-94)
I20260812 06:17:49.200152 18926 log.cc:1079] T e9c34b620f6243d8abfb5e17a5c5f35a P 026c0a7fb56848d3b6553bdf36098dc3: Deleting log segment in path: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460817553-18432-0/minicluster-data/ts-0-root/wals/e9c34b620f6243d8abfb5e17a5c5f35a/wal-000000020 (ops 95-99)
I20260812 06:17:49.200183 18926 log.cc:1079] T e9c34b620f6243d8abfb5e17a5c5f35a P 026c0a7fb56848d3b6553bdf36098dc3: Deleting log segment in path: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460817553-18432-0/minicluster-data/ts-0-root/wals/e9c34b620f6243d8abfb5e17a5c5f35a/wal-000000021 (ops 100-104)
I20260812 06:17:49.200215 18926 log.cc:1079] T e9c34b620f6243d8abfb5e17a5c5f35a P 026c0a7fb56848d3b6553bdf36098dc3: Deleting log segment in path: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460817553-18432-0/minicluster-data/ts-0-root/wals/e9c34b620f6243d8abfb5e17a5c5f35a/wal-000000022 (ops 105-108)
I20260812 06:17:49.200246 18926 log.cc:1079] T e9c34b620f6243d8abfb5e17a5c5f35a P 026c0a7fb56848d3b6553bdf36098dc3: Deleting log segment in path: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460817553-18432-0/minicluster-data/ts-0-root/wals/e9c34b620f6243d8abfb5e17a5c5f35a/wal-000000023 (ops 109-113)
I20260812 06:17:49.200277 18926 log.cc:1079] T e9c34b620f6243d8abfb5e17a5c5f35a P 026c0a7fb56848d3b6553bdf36098dc3: Deleting log segment in path: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460817553-18432-0/minicluster-data/ts-0-root/wals/e9c34b620f6243d8abfb5e17a5c5f35a/wal-000000024 (ops 114-118)
I20260812 06:17:49.200309 18926 log.cc:1079] T e9c34b620f6243d8abfb5e17a5c5f35a P 026c0a7fb56848d3b6553bdf36098dc3: Deleting log segment in path: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460817553-18432-0/minicluster-data/ts-0-root/wals/e9c34b620f6243d8abfb5e17a5c5f35a/wal-000000025 (ops 119-123)
I20260812 06:17:49.200340 18926 log.cc:1079] T e9c34b620f6243d8abfb5e17a5c5f35a P 026c0a7fb56848d3b6553bdf36098dc3: Deleting log segment in path: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460817553-18432-0/minicluster-data/ts-0-root/wals/e9c34b620f6243d8abfb5e17a5c5f35a/wal-000000026 (ops 124-128)
I20260812 06:17:49.200371 18926 log.cc:1079] T e9c34b620f6243d8abfb5e17a5c5f35a P 026c0a7fb56848d3b6553bdf36098dc3: Deleting log segment in path: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460817553-18432-0/minicluster-data/ts-0-root/wals/e9c34b620f6243d8abfb5e17a5c5f35a/wal-000000027 (ops 129-133)
I20260812 06:17:49.221558 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: LogGCOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.022s	user 0.001s	sys 0.020s Metrics: {}
I20260812 06:17:49.222075 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling UndoDeltaBlockGCOp(e9c34b620f6243d8abfb5e17a5c5f35a): 462 bytes on disk
I20260812 06:17:49.222574 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: UndoDeltaBlockGCOp(e9c34b620f6243d8abfb5e17a5c5f35a) 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:17:49.223318 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a): perf score=3.181125
I20260812 06:17:49.238185 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.015s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4077,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:49.238685 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a): perf score=2.188937
I20260812 06:17:49.248377 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3333,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:49.248876 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling MajorDeltaCompactionOp(e9c34b620f6243d8abfb5e17a5c5f35a): perf score=1.000000
I20260812 06:17:49.417855 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: MajorDeltaCompactionOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.169s	user 0.108s	sys 0.052s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918323,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":533,"lbm_read_time_us":11018,"lbm_reads_lt_1ms":674,"lbm_write_time_us":29010,"lbm_writes_lt_1ms":643,"mutex_wait_us":31,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":4864,"thread_start_us":77,"threads_started":1,"update_count":3000}
I20260812 06:17:49.418620 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a): perf score=14.095187
I20260812 06:17:49.476183 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.057s	user 0.043s	sys 0.011s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":25762,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:49.476652 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a): perf score=2.188937
I20260812 06:17:49.487682 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3805,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:49.488217 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling MajorDeltaCompactionOp(e9c34b620f6243d8abfb5e17a5c5f35a): perf score=1.000000
I20260812 06:17:49.643349 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: MajorDeltaCompactionOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.155s	user 0.115s	sys 0.035s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":776,"lbm_read_time_us":8751,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28749,"lbm_writes_lt_1ms":543,"mutex_wait_us":363,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":66944,"update_count":2500}
I20260812 06:17:49.643987 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a): perf score=12.110812
I20260812 06:17:49.683887 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.040s	user 0.018s	sys 0.020s Metrics: {"bytes_written":13948451,"delete_count":0,"lbm_write_time_us":17100,"lbm_writes_lt_1ms":343,"reinsert_count":0,"update_count":1700}
I20260812 06:17:49.684478 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a): perf score=1.196750
I20260812 06:17:49.705693 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.021s	user 0.004s	sys 0.004s Metrics: {"bytes_written":2871909,"delete_count":0,"lbm_write_time_us":3184,"lbm_writes_lt_1ms":73,"reinsert_count":0,"update_count":350}
I20260812 06:17:49.706223 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a): perf score=2.188937
I20260812 06:17:49.715657 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.009s	user 0.006s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3267,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:49.716282 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling MajorDeltaCompactionOp(e9c34b620f6243d8abfb5e17a5c5f35a): perf score=1.000000
I20260812 06:17:49.886191 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: MajorDeltaCompactionOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.170s	user 0.107s	sys 0.052s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815760,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1054,"lbm_read_time_us":12553,"lbm_reads_lt_1ms":573,"lbm_write_time_us":28712,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":542,"mutex_wait_us":338,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8832,"update_count":2500}
I20260812 06:17:49.886792 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a): perf score=14.095187
I20260812 06:17:49.932657 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.046s	user 0.028s	sys 0.015s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":19766,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:49.933390 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling MajorDeltaCompactionOp(e9c34b620f6243d8abfb5e17a5c5f35a): perf score=1.000000
I20260812 06:17:50.087750 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: MajorDeltaCompactionOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.154s	user 0.102s	sys 0.044s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713151,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":882,"dirs.run_cpu_time_us":930,"dirs.run_wall_time_us":6734,"lbm_read_time_us":10952,"lbm_reads_lt_1ms":463,"lbm_write_time_us":23811,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":2000}
I20260812 06:17:50.088346 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a): perf score=11.118625
I20260812 06:17:50.127219 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.039s	user 0.018s	sys 0.020s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":16927,"lbm_writes_lt_1ms":313,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":1550}
I20260812 06:17:50.127694 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a): perf score=2.188937
I20260812 06:17:50.137881 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3495,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:50.138468 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling MajorDeltaCompactionOp(e9c34b620f6243d8abfb5e17a5c5f35a): perf score=1.000000
I20260812 06:17:50.265071 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: MajorDeltaCompactionOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.126s	user 0.110s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713264,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":450,"lbm_read_time_us":9081,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22509,"lbm_writes_lt_1ms":443,"mutex_wait_us":27,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11008,"update_count":2000}
I20260812 06:17:50.265560 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a): perf score=10.126437
I20260812 06:17:50.302380 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.037s	user 0.022s	sys 0.011s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":14756,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:50.302954 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a): perf score=2.188937
I20260812 06:17:50.318913 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.016s	user 0.013s	sys 0.002s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5868,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:50.320132 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling MajorDeltaCompactionOp(e9c34b620f6243d8abfb5e17a5c5f35a): perf score=1.000000
I20260812 06:17:50.434983 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: MajorDeltaCompactionOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.115s	user 0.093s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713270,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1327,"lbm_read_time_us":7574,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21363,"lbm_writes_lt_1ms":443,"mutex_wait_us":407,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:17:50.435580 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a): perf score=10.126437
I20260812 06:17:50.478619 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.043s	user 0.026s	sys 0.011s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16517,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:50.479279 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a): perf score=2.188937
I20260812 06:17:50.490707 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4078,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:50.491451 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling FlushMRSOp(e9c34b620f6243d8abfb5e17a5c5f35a): perf score=1.000000
I20260812 06:17:50.523061 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: FlushMRSOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.031s	user 0.026s	sys 0.005s Metrics: {"bytes_written":1152512,"cfile_init":1,"dirs.queue_time_us":46,"dirs.run_cpu_time_us":209,"dirs.run_wall_time_us":1116,"drs_written":1,"lbm_read_time_us":92,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1741,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:50.523878 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling LogGCOp(e9c34b620f6243d8abfb5e17a5c5f35a): free 112239561 bytes of WAL
I20260812 06:17:50.524130 18926 log_reader.cc:385] T e9c34b620f6243d8abfb5e17a5c5f35a: removed 11 log segments from log reader
I20260812 06:17:50.524178 18926 log.cc:1079] T e9c34b620f6243d8abfb5e17a5c5f35a P 026c0a7fb56848d3b6553bdf36098dc3: Deleting log segment in path: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460817553-18432-0/minicluster-data/ts-0-root/wals/e9c34b620f6243d8abfb5e17a5c5f35a/wal-000000028 (ops 134-138)
I20260812 06:17:50.524207 18926 log.cc:1079] T e9c34b620f6243d8abfb5e17a5c5f35a P 026c0a7fb56848d3b6553bdf36098dc3: Deleting log segment in path: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460817553-18432-0/minicluster-data/ts-0-root/wals/e9c34b620f6243d8abfb5e17a5c5f35a/wal-000000029 (ops 139-142)
I20260812 06:17:50.524224 18926 log.cc:1079] T e9c34b620f6243d8abfb5e17a5c5f35a P 026c0a7fb56848d3b6553bdf36098dc3: Deleting log segment in path: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460817553-18432-0/minicluster-data/ts-0-root/wals/e9c34b620f6243d8abfb5e17a5c5f35a/wal-000000030 (ops 143-147)
I20260812 06:17:50.524251 18926 log.cc:1079] T e9c34b620f6243d8abfb5e17a5c5f35a P 026c0a7fb56848d3b6553bdf36098dc3: Deleting log segment in path: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460817553-18432-0/minicluster-data/ts-0-root/wals/e9c34b620f6243d8abfb5e17a5c5f35a/wal-000000031 (ops 148-152)
I20260812 06:17:50.524282 18926 log.cc:1079] T e9c34b620f6243d8abfb5e17a5c5f35a P 026c0a7fb56848d3b6553bdf36098dc3: Deleting log segment in path: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460817553-18432-0/minicluster-data/ts-0-root/wals/e9c34b620f6243d8abfb5e17a5c5f35a/wal-000000032 (ops 153-157)
I20260812 06:17:50.524314 18926 log.cc:1079] T e9c34b620f6243d8abfb5e17a5c5f35a P 026c0a7fb56848d3b6553bdf36098dc3: Deleting log segment in path: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460817553-18432-0/minicluster-data/ts-0-root/wals/e9c34b620f6243d8abfb5e17a5c5f35a/wal-000000033 (ops 158-162)
I20260812 06:17:50.524348 18926 log.cc:1079] T e9c34b620f6243d8abfb5e17a5c5f35a P 026c0a7fb56848d3b6553bdf36098dc3: Deleting log segment in path: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460817553-18432-0/minicluster-data/ts-0-root/wals/e9c34b620f6243d8abfb5e17a5c5f35a/wal-000000034 (ops 163-167)
I20260812 06:17:50.524381 18926 log.cc:1079] T e9c34b620f6243d8abfb5e17a5c5f35a P 026c0a7fb56848d3b6553bdf36098dc3: Deleting log segment in path: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460817553-18432-0/minicluster-data/ts-0-root/wals/e9c34b620f6243d8abfb5e17a5c5f35a/wal-000000035 (ops 168-172)
I20260812 06:17:50.524413 18926 log.cc:1079] T e9c34b620f6243d8abfb5e17a5c5f35a P 026c0a7fb56848d3b6553bdf36098dc3: Deleting log segment in path: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460817553-18432-0/minicluster-data/ts-0-root/wals/e9c34b620f6243d8abfb5e17a5c5f35a/wal-000000036 (ops 173-177)
I20260812 06:17:50.524446 18926 log.cc:1079] T e9c34b620f6243d8abfb5e17a5c5f35a P 026c0a7fb56848d3b6553bdf36098dc3: Deleting log segment in path: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460817553-18432-0/minicluster-data/ts-0-root/wals/e9c34b620f6243d8abfb5e17a5c5f35a/wal-000000037 (ops 178-182)
I20260812 06:17:50.524477 18926 log.cc:1079] T e9c34b620f6243d8abfb5e17a5c5f35a P 026c0a7fb56848d3b6553bdf36098dc3: Deleting log segment in path: /tmp/dist-test-taskkg4RHB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460817553-18432-0/minicluster-data/ts-0-root/wals/e9c34b620f6243d8abfb5e17a5c5f35a/wal-000000038 (ops 183-187)
I20260812 06:17:50.542491 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: LogGCOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.018s	user 0.000s	sys 0.018s Metrics: {}
I20260812 06:17:50.543022 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling UndoDeltaBlockGCOp(e9c34b620f6243d8abfb5e17a5c5f35a): 448 bytes on disk
I20260812 06:17:50.543527 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: UndoDeltaBlockGCOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4}
I20260812 06:17:50.544094 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a): perf score=2.188937
I20260812 06:17:50.564405 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.020s	user 0.007s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5622,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:50.564894 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a): perf score=2.188937
I20260812 06:17:50.575130 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3741,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:50.575627 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling MajorDeltaCompactionOp(e9c34b620f6243d8abfb5e17a5c5f35a): perf score=1.000000
I20260812 06:17:50.742259 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: MajorDeltaCompactionOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.166s	user 0.106s	sys 0.048s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918335,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":625,"lbm_read_time_us":12351,"lbm_reads_lt_1ms":674,"lbm_write_time_us":29405,"lbm_writes_lt_1ms":643,"mutex_wait_us":56,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":14208,"thread_start_us":80,"threads_started":1,"update_count":3000}
I20260812 06:17:50.743072 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a): perf score=14.095187
I20260812 06:17:50.786027 18432 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.621s	user 1.670s	sys 0.124s
I20260812 06:17:50.790166 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.047s	user 0.032s	sys 0.008s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":16993,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:50.790719 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a): perf score=2.188937
I20260812 06:17:50.800482 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: FlushDeltaMemStoresOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.010s	user 0.001s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3980,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:50.800915 19054 maintenance_manager.cc:419] P 026c0a7fb56848d3b6553bdf36098dc3: Scheduling MajorDeltaCompactionOp(e9c34b620f6243d8abfb5e17a5c5f35a): perf score=1.000000
I20260812 06:17:50.828372 18432 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.042s	user 0.001s	sys 0.000s
I20260812 06:17:50.828955 18432 tablet_server.cc:179] TabletServer@127.18.0.1:0 shutting down...
I20260812 06:17:50.906989 18926 maintenance_manager.cc:643] P 026c0a7fb56848d3b6553bdf36098dc3: MajorDeltaCompactionOp(e9c34b620f6243d8abfb5e17a5c5f35a) complete. Timing: real 0.106s	user 0.082s	sys 0.024s Metrics: {"cfile_cache_hit":401,"cfile_cache_hit_bytes":16409766,"cfile_cache_miss":131,"cfile_cache_miss_bytes":8405916,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":266,"lbm_read_time_us":3167,"lbm_reads_lt_1ms":163,"lbm_write_time_us":23465,"lbm_writes_lt_1ms":543,"mutex_wait_us":53,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":65664,"update_count":2500}
I20260812 06:17:50.907724 18432 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:50.907945 18432 tablet_replica.cc:333] T e9c34b620f6243d8abfb5e17a5c5f35a P 026c0a7fb56848d3b6553bdf36098dc3: stopping tablet replica
I20260812 06:17:50.908109 18432 raft_consensus.cc:2243] T e9c34b620f6243d8abfb5e17a5c5f35a P 026c0a7fb56848d3b6553bdf36098dc3 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:50.908264 18432 raft_consensus.cc:2272] T e9c34b620f6243d8abfb5e17a5c5f35a P 026c0a7fb56848d3b6553bdf36098dc3 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:50.922640 18432 tablet_server.cc:196] TabletServer@127.18.0.1:0 shutdown complete.
I20260812 06:17:50.951503 18432 master.cc:562] Master@127.18.0.62:45431 shutting down...
I20260812 06:17:50.954516 18432 raft_consensus.cc:2243] T 00000000000000000000000000000000 P c5e86151b9e247cb855d904a30906476 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:50.954703 18432 raft_consensus.cc:2272] T 00000000000000000000000000000000 P c5e86151b9e247cb855d904a30906476 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:50.954768 18432 tablet_replica.cc:333] T 00000000000000000000000000000000 P c5e86151b9e247cb855d904a30906476: stopping tablet replica
I20260812 06:17:50.967056 18432 master.cc:584] Master@127.18.0.62:45431 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5058 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10209 ms total)

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