[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:18:47.612629   532 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.0.133.62:39305
I20260812 06:18:47.613608   532 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:18:47.614203   532 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:47.620468   544 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:47.620468   540 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:47.620463   542 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:47.621088   532 server_base.cc:1061] running on GCE node
I20260812 06:18:47.621557   532 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:47.621676   532 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:47.621733   532 hybrid_clock.cc:648] HybridClock initialized: now 1786515527621731 us; error 0 us; skew 500 ppm
I20260812 06:18:47.623652   532 webserver.cc:533] Webserver started at http://127.0.133.62:39637/ using document root <none> and password file <none>
I20260812 06:18:47.624214   532 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:47.624301   532 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:47.624575   532 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:47.626384   532 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515527602152-532-0/minicluster-data/master-0-root/instance:
uuid: "a9593c8860c8487ea71ae83002ee581e"
format_stamp: "Formatted at 2026-08-12 06:18:47 on dist-test-slave-7nm7"
I20260812 06:18:47.629894   532 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:47.632028   553 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:47.633028   532 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:18:47.633164   532 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515527602152-532-0/minicluster-data/master-0-root
uuid: "a9593c8860c8487ea71ae83002ee581e"
format_stamp: "Formatted at 2026-08-12 06:18:47 on dist-test-slave-7nm7"
I20260812 06:18:47.633289   532 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515527602152-532-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515527602152-532-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515527602152-532-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:47.643527   532 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:47.644107   532 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:18:47.644289   532 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:47.651813   532 rpc_server.cc:307] RPC server started. Bound to: 127.0.133.62:39305
I20260812 06:18:47.651844   650 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.0.133.62:39305 every 8 connection(s)
I20260812 06:18:47.653939   652 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:47.659128   652 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a9593c8860c8487ea71ae83002ee581e: Bootstrap starting.
I20260812 06:18:47.661322   652 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P a9593c8860c8487ea71ae83002ee581e: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:47.662127   652 log.cc:826] T 00000000000000000000000000000000 P a9593c8860c8487ea71ae83002ee581e: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:47.663720   652 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a9593c8860c8487ea71ae83002ee581e: No bootstrap required, opened a new log
I20260812 06:18:47.666296   652 raft_consensus.cc:359] T 00000000000000000000000000000000 P a9593c8860c8487ea71ae83002ee581e [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a9593c8860c8487ea71ae83002ee581e" member_type: VOTER }
I20260812 06:18:47.666445   652 raft_consensus.cc:385] T 00000000000000000000000000000000 P a9593c8860c8487ea71ae83002ee581e [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:47.666489   652 raft_consensus.cc:740] T 00000000000000000000000000000000 P a9593c8860c8487ea71ae83002ee581e [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: a9593c8860c8487ea71ae83002ee581e, State: Initialized, Role: FOLLOWER
I20260812 06:18:47.666962   652 consensus_queue.cc:260] T 00000000000000000000000000000000 P a9593c8860c8487ea71ae83002ee581e [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: "a9593c8860c8487ea71ae83002ee581e" member_type: VOTER }
I20260812 06:18:47.667093   652 raft_consensus.cc:399] T 00000000000000000000000000000000 P a9593c8860c8487ea71ae83002ee581e [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:47.667138   652 raft_consensus.cc:493] T 00000000000000000000000000000000 P a9593c8860c8487ea71ae83002ee581e [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:47.667223   652 raft_consensus.cc:3060] T 00000000000000000000000000000000 P a9593c8860c8487ea71ae83002ee581e [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:47.667892   652 raft_consensus.cc:515] T 00000000000000000000000000000000 P a9593c8860c8487ea71ae83002ee581e [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a9593c8860c8487ea71ae83002ee581e" member_type: VOTER }
I20260812 06:18:47.668267   652 leader_election.cc:304] T 00000000000000000000000000000000 P a9593c8860c8487ea71ae83002ee581e [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: a9593c8860c8487ea71ae83002ee581e; no voters: 
I20260812 06:18:47.668514   652 leader_election.cc:290] T 00000000000000000000000000000000 P a9593c8860c8487ea71ae83002ee581e [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:47.668653   657 raft_consensus.cc:2804] T 00000000000000000000000000000000 P a9593c8860c8487ea71ae83002ee581e [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:47.668924   657 raft_consensus.cc:697] T 00000000000000000000000000000000 P a9593c8860c8487ea71ae83002ee581e [term 1 LEADER]: Becoming Leader. State: Replica: a9593c8860c8487ea71ae83002ee581e, State: Running, Role: LEADER
I20260812 06:18:47.669339   657 consensus_queue.cc:237] T 00000000000000000000000000000000 P a9593c8860c8487ea71ae83002ee581e [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: "a9593c8860c8487ea71ae83002ee581e" member_type: VOTER }
I20260812 06:18:47.669513   652 sys_catalog.cc:565] T 00000000000000000000000000000000 P a9593c8860c8487ea71ae83002ee581e [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:47.671115   659 sys_catalog.cc:455] T 00000000000000000000000000000000 P a9593c8860c8487ea71ae83002ee581e [sys.catalog]: SysCatalogTable state changed. Reason: New leader a9593c8860c8487ea71ae83002ee581e. Latest consensus state: current_term: 1 leader_uuid: "a9593c8860c8487ea71ae83002ee581e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a9593c8860c8487ea71ae83002ee581e" member_type: VOTER } }
I20260812 06:18:47.671236   659 sys_catalog.cc:458] T 00000000000000000000000000000000 P a9593c8860c8487ea71ae83002ee581e [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:47.671608   675 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:47.671576   658 sys_catalog.cc:455] T 00000000000000000000000000000000 P a9593c8860c8487ea71ae83002ee581e [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "a9593c8860c8487ea71ae83002ee581e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a9593c8860c8487ea71ae83002ee581e" member_type: VOTER } }
I20260812 06:18:47.671721   658 sys_catalog.cc:458] T 00000000000000000000000000000000 P a9593c8860c8487ea71ae83002ee581e [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:47.671795   532 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:47.673748   675 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:47.677795   675 catalog_manager.cc:1383] Generated new cluster ID: 2adaf641c12e4dacb88c58fd243d3e24
I20260812 06:18:47.677860   675 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:47.718371   675 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:47.719257   675 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:47.730453   675 catalog_manager.cc:6092] T 00000000000000000000000000000000 P a9593c8860c8487ea71ae83002ee581e: Generated new TSK 0
I20260812 06:18:47.731045   675 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:47.736562   532 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:47.739534   698 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:47.739559   693 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:47.739727   532 server_base.cc:1061] running on GCE node
W20260812 06:18:47.739559   687 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:18:47.740074   532 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:47.740120   532 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:47.740135   532 hybrid_clock.cc:648] HybridClock initialized: now 1786515527740135 us; error 0 us; skew 500 ppm
I20260812 06:18:47.741127   532 webserver.cc:533] Webserver started at http://127.0.133.1:35051/ using document root <none> and password file <none>
I20260812 06:18:47.741317   532 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:47.741376   532 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:47.741473   532 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:47.741855   532 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515527602152-532-0/minicluster-data/ts-0-root/instance:
uuid: "2ab4b95a840940c18330f1b983b856bd"
format_stamp: "Formatted at 2026-08-12 06:18:47 on dist-test-slave-7nm7"
I20260812 06:18:47.743438   532 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:18:47.744450   710 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:47.744743   532 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:47.744835   532 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515527602152-532-0/minicluster-data/ts-0-root
uuid: "2ab4b95a840940c18330f1b983b856bd"
format_stamp: "Formatted at 2026-08-12 06:18:47 on dist-test-slave-7nm7"
I20260812 06:18:47.744918   532 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515527602152-532-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515527602152-532-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515527602152-532-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:47.767190   532 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:47.767627   532 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:47.768119   532 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:47.768939   532 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:47.769029   532 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:47.769109   532 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:47.769161   532 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:47.776196   532 rpc_server.cc:307] RPC server started. Bound to: 127.0.133.1:35895
I20260812 06:18:47.776253   816 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.0.133.1:35895 every 8 connection(s)
I20260812 06:18:47.789305   818 heartbeater.cc:344] Connected to a master server at 127.0.133.62:39305
I20260812 06:18:47.789551   818 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:47.790016   818 heartbeater.cc:507] Master 127.0.133.62:39305 requested a full tablet report, sending...
I20260812 06:18:47.791473   577 ts_manager.cc:194] Registered new tserver with Master: 2ab4b95a840940c18330f1b983b856bd (127.0.133.1:35895)
I20260812 06:18:47.791620   532 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.014809564s
I20260812 06:18:47.793143   577 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:35258
I20260812 06:18:47.801133   577 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:35268:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:47.815322   760 tablet_service.cc:1511] Processing CreateTablet for tablet 0b0c756edb80470283cbd69959730681 (DEFAULT_TABLE table=heavy-update-compaction-test [id=0d636ba437604f038d700d22cb78ad69]), partition=
I20260812 06:18:47.815822   760 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 0b0c756edb80470283cbd69959730681. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:47.818071   845 tablet_bootstrap.cc:492] T 0b0c756edb80470283cbd69959730681 P 2ab4b95a840940c18330f1b983b856bd: Bootstrap starting.
I20260812 06:18:47.819766   845 tablet_bootstrap.cc:654] T 0b0c756edb80470283cbd69959730681 P 2ab4b95a840940c18330f1b983b856bd: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:47.821213   845 tablet_bootstrap.cc:492] T 0b0c756edb80470283cbd69959730681 P 2ab4b95a840940c18330f1b983b856bd: No bootstrap required, opened a new log
I20260812 06:18:47.821313   845 ts_tablet_manager.cc:1403] T 0b0c756edb80470283cbd69959730681 P 2ab4b95a840940c18330f1b983b856bd: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:18:47.821852   845 raft_consensus.cc:359] T 0b0c756edb80470283cbd69959730681 P 2ab4b95a840940c18330f1b983b856bd [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2ab4b95a840940c18330f1b983b856bd" member_type: VOTER last_known_addr { host: "127.0.133.1" port: 35895 } }
I20260812 06:18:47.821964   845 raft_consensus.cc:385] T 0b0c756edb80470283cbd69959730681 P 2ab4b95a840940c18330f1b983b856bd [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:47.822041   845 raft_consensus.cc:740] T 0b0c756edb80470283cbd69959730681 P 2ab4b95a840940c18330f1b983b856bd [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 2ab4b95a840940c18330f1b983b856bd, State: Initialized, Role: FOLLOWER
I20260812 06:18:47.822299   845 consensus_queue.cc:260] T 0b0c756edb80470283cbd69959730681 P 2ab4b95a840940c18330f1b983b856bd [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: "2ab4b95a840940c18330f1b983b856bd" member_type: VOTER last_known_addr { host: "127.0.133.1" port: 35895 } }
I20260812 06:18:47.822431   845 raft_consensus.cc:399] T 0b0c756edb80470283cbd69959730681 P 2ab4b95a840940c18330f1b983b856bd [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:47.822542   845 raft_consensus.cc:493] T 0b0c756edb80470283cbd69959730681 P 2ab4b95a840940c18330f1b983b856bd [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:47.822613   845 raft_consensus.cc:3060] T 0b0c756edb80470283cbd69959730681 P 2ab4b95a840940c18330f1b983b856bd [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:47.823518   845 raft_consensus.cc:515] T 0b0c756edb80470283cbd69959730681 P 2ab4b95a840940c18330f1b983b856bd [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2ab4b95a840940c18330f1b983b856bd" member_type: VOTER last_known_addr { host: "127.0.133.1" port: 35895 } }
I20260812 06:18:47.823680   845 leader_election.cc:304] T 0b0c756edb80470283cbd69959730681 P 2ab4b95a840940c18330f1b983b856bd [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: 2ab4b95a840940c18330f1b983b856bd; no voters: 
I20260812 06:18:47.823949   845 leader_election.cc:290] T 0b0c756edb80470283cbd69959730681 P 2ab4b95a840940c18330f1b983b856bd [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:47.824056   848 raft_consensus.cc:2804] T 0b0c756edb80470283cbd69959730681 P 2ab4b95a840940c18330f1b983b856bd [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:47.824258   848 raft_consensus.cc:697] T 0b0c756edb80470283cbd69959730681 P 2ab4b95a840940c18330f1b983b856bd [term 1 LEADER]: Becoming Leader. State: Replica: 2ab4b95a840940c18330f1b983b856bd, State: Running, Role: LEADER
I20260812 06:18:47.824365   845 ts_tablet_manager.cc:1434] T 0b0c756edb80470283cbd69959730681 P 2ab4b95a840940c18330f1b983b856bd: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:47.824491   848 consensus_queue.cc:237] T 0b0c756edb80470283cbd69959730681 P 2ab4b95a840940c18330f1b983b856bd [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: "2ab4b95a840940c18330f1b983b856bd" member_type: VOTER last_known_addr { host: "127.0.133.1" port: 35895 } }
I20260812 06:18:47.824633   818 heartbeater.cc:499] Master 127.0.133.62:39305 was elected leader, sending a full tablet report...
I20260812 06:18:47.827307   577 catalog_manager.cc:5719] T 0b0c756edb80470283cbd69959730681 P 2ab4b95a840940c18330f1b983b856bd reported cstate change: term changed from 0 to 1, leader changed from <none> to 2ab4b95a840940c18330f1b983b856bd (127.0.133.1). New cstate: current_term: 1 leader_uuid: "2ab4b95a840940c18330f1b983b856bd" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2ab4b95a840940c18330f1b983b856bd" member_type: VOTER last_known_addr { host: "127.0.133.1" port: 35895 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:47.899518   532 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.064s	user 0.025s	sys 0.004s
I20260812 06:18:48.027278   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling FlushMRSOp(0b0c756edb80470283cbd69959730681): perf score=15.086190
I20260812 06:18:48.181758   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: FlushMRSOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.154s	user 0.114s	sys 0.036s Metrics: {"bytes_written":8697371,"cfile_init":1,"compiler_manager_pool.queue_time_us":294,"delete_count":0,"dirs.queue_time_us":51,"dirs.run_cpu_time_us":185,"dirs.run_wall_time_us":864,"drs_written":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4,"lbm_write_time_us":39016,"lbm_writes_lt_1ms":569,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"spinlock_wait_cycles":49536,"thread_start_us":123,"threads_started":1,"update_count":1060}
I20260812 06:18:48.182896   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling LogGCOp(0b0c756edb80470283cbd69959730681): free 8725963 bytes of WAL
I20260812 06:18:48.183226   718 log_reader.cc:385] T 0b0c756edb80470283cbd69959730681: removed 1 log segments from log reader
I20260812 06:18:48.183311   718 log.cc:1079] T 0b0c756edb80470283cbd69959730681 P 2ab4b95a840940c18330f1b983b856bd: Deleting log segment in path: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515527602152-532-0/minicluster-data/ts-0-root/wals/0b0c756edb80470283cbd69959730681/wal-000000001 (ops 1-6)
I20260812 06:18:48.185352   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: LogGCOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:18:48.185716   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681): perf score=2.188937
I20260812 06:18:48.205817   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.020s	user 0.007s	sys 0.008s Metrics: {"bytes_written":3610355,"delete_count":0,"lbm_write_time_us":6372,"lbm_writes_lt_1ms":91,"reinsert_count":0,"update_count":440}
I20260812 06:18:48.206429   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling UndoDeltaBlockGCOp(0b0c756edb80470283cbd69959730681): 12308958 bytes on disk
I20260812 06:18:48.207023   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: UndoDeltaBlockGCOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4}
I20260812 06:18:48.207551   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling MajorDeltaCompactionOp(0b0c756edb80470283cbd69959730681): perf score=1.000000
I20260812 06:18:48.324162   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: MajorDeltaCompactionOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.116s	user 0.084s	sys 0.032s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16528889,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":890,"lbm_read_time_us":7654,"lbm_reads_lt_1ms":360,"lbm_write_time_us":20711,"lbm_writes_lt_1ms":343,"mutex_wait_us":57,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":16256,"thread_start_us":325,"threads_started":5,"update_count":1500}
I20260812 06:18:48.324702   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681): perf score=10.126437
I20260812 06:18:48.376858   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.052s	user 0.032s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20749,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:48.377421   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681): perf score=2.188937
I20260812 06:18:48.391004   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.013s	user 0.009s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5090,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:48.391850   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling MajorDeltaCompactionOp(0b0c756edb80470283cbd69959730681): perf score=1.000000
I20260812 06:18:48.528220   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: MajorDeltaCompactionOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.136s	user 0.101s	sys 0.035s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1235,"lbm_read_time_us":9915,"lbm_reads_lt_1ms":468,"lbm_write_time_us":27631,"lbm_writes_lt_1ms":443,"mutex_wait_us":354,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2048,"update_count":2000}
I20260812 06:18:48.528842   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681): perf score=10.126437
I20260812 06:18:48.582213   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.053s	user 0.021s	sys 0.028s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18355,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:48.582839   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681): perf score=2.188937
I20260812 06:18:48.594857   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.012s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4615,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:48.595305   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling MajorDeltaCompactionOp(0b0c756edb80470283cbd69959730681): perf score=1.000000
I20260812 06:18:48.753512   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: MajorDeltaCompactionOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.158s	user 0.106s	sys 0.052s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":647,"lbm_read_time_us":14471,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25938,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:18:48.754377   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681): perf score=10.126437
I20260812 06:18:48.803547   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.049s	user 0.024s	sys 0.021s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":21612,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:48.804090   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681): perf score=2.188937
I20260812 06:18:48.815840   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4473,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:48.816325   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling MajorDeltaCompactionOp(0b0c756edb80470283cbd69959730681): perf score=1.000000
I20260812 06:18:48.945384   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: MajorDeltaCompactionOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.129s	user 0.101s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":266,"lbm_read_time_us":10780,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25843,"lbm_writes_lt_1ms":443,"mutex_wait_us":70,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2000}
I20260812 06:18:48.945951   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681): perf score=10.126437
I20260812 06:18:48.988435   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.042s	user 0.019s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19863,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:48.988912   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681): perf score=2.188937
I20260812 06:18:49.008006   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.019s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5684,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:49.008561   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling MajorDeltaCompactionOp(0b0c756edb80470283cbd69959730681): perf score=1.000000
I20260812 06:18:49.138443   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: MajorDeltaCompactionOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.130s	user 0.075s	sys 0.052s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":618,"lbm_read_time_us":9063,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26393,"lbm_writes_lt_1ms":443,"mutex_wait_us":46,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11264,"update_count":2000}
I20260812 06:18:49.139158   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681): perf score=11.118625
I20260812 06:18:49.195989   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.057s	user 0.027s	sys 0.028s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":23590,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:18:49.196648   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681): perf score=2.188937
I20260812 06:18:49.215298   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.018s	user 0.008s	sys 0.008s Metrics: {"bytes_written":4102660,"delete_count":0,"lbm_write_time_us":7052,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:49.215801   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681): perf score=2.188937
I20260812 06:18:49.225382   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3763,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:49.225835   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling MajorDeltaCompactionOp(0b0c756edb80470283cbd69959730681): perf score=1.000000
I20260812 06:18:49.402665   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: MajorDeltaCompactionOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.177s	user 0.136s	sys 0.032s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733834,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":2624,"lbm_read_time_us":13446,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30436,"lbm_writes_lt_1ms":543,"mutex_wait_us":844,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13568,"update_count":2500}
I20260812 06:18:49.403393   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681): perf score=14.095187
I20260812 06:18:49.478119   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.075s	user 0.019s	sys 0.051s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":28527,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:49.478802   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681): perf score=2.188937
I20260812 06:18:49.489670   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4268,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:49.490145   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling FlushMRSOp(0b0c756edb80470283cbd69959730681): perf score=1.000000
I20260812 06:18:49.531006   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: FlushMRSOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.041s	user 0.030s	sys 0.009s Metrics: {"bytes_written":1193504,"cfile_init":1,"dirs.queue_time_us":90,"dirs.run_cpu_time_us":251,"dirs.run_wall_time_us":1215,"drs_written":1,"lbm_read_time_us":76,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2215,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:49.532157   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling MajorDeltaCompactionOp(0b0c756edb80470283cbd69959730681): perf score=1.000000
I20260812 06:18:49.724661   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: MajorDeltaCompactionOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.192s	user 0.132s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":501,"lbm_read_time_us":15789,"lbm_reads_lt_1ms":564,"lbm_write_time_us":33521,"lbm_writes_lt_1ms":543,"mutex_wait_us":310,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13696,"update_count":2500}
I20260812 06:18:49.725342   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling LogGCOp(0b0c756edb80470283cbd69959730681): free 124257234 bytes of WAL
I20260812 06:18:49.725622   718 log_reader.cc:385] T 0b0c756edb80470283cbd69959730681: removed 12 log segments from log reader
I20260812 06:18:49.725701   718 log.cc:1079] T 0b0c756edb80470283cbd69959730681 P 2ab4b95a840940c18330f1b983b856bd: Deleting log segment in path: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515527602152-532-0/minicluster-data/ts-0-root/wals/0b0c756edb80470283cbd69959730681/wal-000000002 (ops 7-11)
I20260812 06:18:49.725772   718 log.cc:1079] T 0b0c756edb80470283cbd69959730681 P 2ab4b95a840940c18330f1b983b856bd: Deleting log segment in path: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515527602152-532-0/minicluster-data/ts-0-root/wals/0b0c756edb80470283cbd69959730681/wal-000000003 (ops 12-16)
I20260812 06:18:49.725835   718 log.cc:1079] T 0b0c756edb80470283cbd69959730681 P 2ab4b95a840940c18330f1b983b856bd: Deleting log segment in path: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515527602152-532-0/minicluster-data/ts-0-root/wals/0b0c756edb80470283cbd69959730681/wal-000000004 (ops 17-21)
I20260812 06:18:49.725908   718 log.cc:1079] T 0b0c756edb80470283cbd69959730681 P 2ab4b95a840940c18330f1b983b856bd: Deleting log segment in path: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515527602152-532-0/minicluster-data/ts-0-root/wals/0b0c756edb80470283cbd69959730681/wal-000000005 (ops 22-26)
I20260812 06:18:49.725986   718 log.cc:1079] T 0b0c756edb80470283cbd69959730681 P 2ab4b95a840940c18330f1b983b856bd: Deleting log segment in path: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515527602152-532-0/minicluster-data/ts-0-root/wals/0b0c756edb80470283cbd69959730681/wal-000000006 (ops 27-31)
I20260812 06:18:49.726061   718 log.cc:1079] T 0b0c756edb80470283cbd69959730681 P 2ab4b95a840940c18330f1b983b856bd: Deleting log segment in path: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515527602152-532-0/minicluster-data/ts-0-root/wals/0b0c756edb80470283cbd69959730681/wal-000000007 (ops 32-36)
I20260812 06:18:49.726135   718 log.cc:1079] T 0b0c756edb80470283cbd69959730681 P 2ab4b95a840940c18330f1b983b856bd: Deleting log segment in path: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515527602152-532-0/minicluster-data/ts-0-root/wals/0b0c756edb80470283cbd69959730681/wal-000000008 (ops 37-40)
I20260812 06:18:49.726222   718 log.cc:1079] T 0b0c756edb80470283cbd69959730681 P 2ab4b95a840940c18330f1b983b856bd: Deleting log segment in path: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515527602152-532-0/minicluster-data/ts-0-root/wals/0b0c756edb80470283cbd69959730681/wal-000000009 (ops 41-45)
I20260812 06:18:49.726343   718 log.cc:1079] T 0b0c756edb80470283cbd69959730681 P 2ab4b95a840940c18330f1b983b856bd: Deleting log segment in path: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515527602152-532-0/minicluster-data/ts-0-root/wals/0b0c756edb80470283cbd69959730681/wal-000000010 (ops 46-50)
I20260812 06:18:49.726421   718 log.cc:1079] T 0b0c756edb80470283cbd69959730681 P 2ab4b95a840940c18330f1b983b856bd: Deleting log segment in path: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515527602152-532-0/minicluster-data/ts-0-root/wals/0b0c756edb80470283cbd69959730681/wal-000000011 (ops 51-55)
I20260812 06:18:49.726500   718 log.cc:1079] T 0b0c756edb80470283cbd69959730681 P 2ab4b95a840940c18330f1b983b856bd: Deleting log segment in path: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515527602152-532-0/minicluster-data/ts-0-root/wals/0b0c756edb80470283cbd69959730681/wal-000000012 (ops 56-60)
I20260812 06:18:49.726598   718 log.cc:1079] T 0b0c756edb80470283cbd69959730681 P 2ab4b95a840940c18330f1b983b856bd: Deleting log segment in path: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515527602152-532-0/minicluster-data/ts-0-root/wals/0b0c756edb80470283cbd69959730681/wal-000000013 (ops 61-65)
I20260812 06:18:49.767825   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: LogGCOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.042s	user 0.000s	sys 0.040s Metrics: {}
I20260812 06:18:49.768337   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling UndoDeltaBlockGCOp(0b0c756edb80470283cbd69959730681): 463 bytes on disk
I20260812 06:18:49.768810   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: UndoDeltaBlockGCOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":74,"lbm_reads_lt_1ms":4}
I20260812 06:18:49.769366   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681): perf score=18.063937
I20260812 06:18:49.840348   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.071s	user 0.024s	sys 0.044s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":27943,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:49.841059   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681): perf score=2.188937
I20260812 06:18:49.859335   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.018s	user 0.015s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7087,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:49.859884   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling MajorDeltaCompactionOp(0b0c756edb80470283cbd69959730681): perf score=1.000000
I20260812 06:18:50.059871   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: MajorDeltaCompactionOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.200s	user 0.119s	sys 0.080s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28836139,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":779,"lbm_read_time_us":17348,"lbm_reads_lt_1ms":672,"lbm_write_time_us":35331,"lbm_writes_lt_1ms":643,"mutex_wait_us":20,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":13952,"update_count":3000}
I20260812 06:18:50.060566   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681): perf score=14.095187
I20260812 06:18:50.119124   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.058s	user 0.022s	sys 0.035s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":27284,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:50.119692   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681): perf score=2.188937
I20260812 06:18:50.132736   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.013s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5391,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:50.133167   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling MajorDeltaCompactionOp(0b0c756edb80470283cbd69959730681): perf score=1.000000
I20260812 06:18:50.308851   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: MajorDeltaCompactionOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.176s	user 0.123s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":190,"lbm_read_time_us":14583,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31090,"lbm_writes_lt_1ms":543,"mutex_wait_us":46,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":66688,"update_count":2500}
I20260812 06:18:50.309554   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681): perf score=14.095187
I20260812 06:18:50.379653   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.070s	user 0.025s	sys 0.042s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":26021,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:18:50.380399   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681): perf score=2.188937
I20260812 06:18:50.402791   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.022s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6775,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:50.403332   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling MajorDeltaCompactionOp(0b0c756edb80470283cbd69959730681): perf score=1.000000
I20260812 06:18:50.601873   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: MajorDeltaCompactionOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.198s	user 0.152s	sys 0.043s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733725,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":850,"lbm_read_time_us":14617,"lbm_reads_lt_1ms":564,"lbm_write_time_us":34439,"lbm_writes_lt_1ms":543,"mutex_wait_us":315,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4608,"update_count":2500}
I20260812 06:18:50.602521   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681): perf score=14.095187
I20260812 06:18:50.674957   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.072s	user 0.042s	sys 0.026s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24565,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:50.675638   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681): perf score=2.188937
I20260812 06:18:50.686499   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4286,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:50.686921   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling MajorDeltaCompactionOp(0b0c756edb80470283cbd69959730681): perf score=1.000000
I20260812 06:18:50.864596   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: MajorDeltaCompactionOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.178s	user 0.127s	sys 0.049s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":175,"lbm_read_time_us":13283,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30205,"lbm_writes_lt_1ms":543,"mutex_wait_us":47,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10112,"update_count":2500}
I20260812 06:18:50.865362   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681): perf score=11.118625
I20260812 06:18:50.900149   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.035s	user 0.013s	sys 0.020s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":15151,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:50.900635   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681): perf score=2.188937
I20260812 06:18:50.924834   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.024s	user 0.003s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5015,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:50.925292   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681): perf score=2.188937
I20260812 06:18:50.948895   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.023s	user 0.010s	sys 0.011s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4880,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:50.949460   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling MajorDeltaCompactionOp(0b0c756edb80470283cbd69959730681): perf score=1.000000
I20260812 06:18:51.134148   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: MajorDeltaCompactionOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.184s	user 0.136s	sys 0.044s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733834,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":196,"lbm_read_time_us":12386,"lbm_reads_lt_1ms":573,"lbm_write_time_us":31284,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8320,"update_count":2500}
I20260812 06:18:51.134723   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681): perf score=11.118625
I20260812 06:18:51.176126   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.041s	user 0.028s	sys 0.011s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":17817,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:51.176872   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681): perf score=2.188937
I20260812 06:18:51.195513   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.017s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4771,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:51.196182   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling FlushMRSOp(0b0c756edb80470283cbd69959730681): perf score=1.000000
I20260812 06:18:51.259831   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: FlushMRSOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.063s	user 0.028s	sys 0.015s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":56,"dirs.run_cpu_time_us":237,"dirs.run_wall_time_us":1241,"drs_written":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2518,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:51.260794   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling LogGCOp(0b0c756edb80470283cbd69959730681): free 120553331 bytes of WAL
I20260812 06:18:51.261091   718 log_reader.cc:385] T 0b0c756edb80470283cbd69959730681: removed 12 log segments from log reader
I20260812 06:18:51.261170   718 log.cc:1079] T 0b0c756edb80470283cbd69959730681 P 2ab4b95a840940c18330f1b983b856bd: Deleting log segment in path: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515527602152-532-0/minicluster-data/ts-0-root/wals/0b0c756edb80470283cbd69959730681/wal-000000014 (ops 66-70)
I20260812 06:18:51.261225   718 log.cc:1079] T 0b0c756edb80470283cbd69959730681 P 2ab4b95a840940c18330f1b983b856bd: Deleting log segment in path: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515527602152-532-0/minicluster-data/ts-0-root/wals/0b0c756edb80470283cbd69959730681/wal-000000015 (ops 71-75)
I20260812 06:18:51.261286   718 log.cc:1079] T 0b0c756edb80470283cbd69959730681 P 2ab4b95a840940c18330f1b983b856bd: Deleting log segment in path: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515527602152-532-0/minicluster-data/ts-0-root/wals/0b0c756edb80470283cbd69959730681/wal-000000016 (ops 76-80)
I20260812 06:18:51.261329   718 log.cc:1079] T 0b0c756edb80470283cbd69959730681 P 2ab4b95a840940c18330f1b983b856bd: Deleting log segment in path: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515527602152-532-0/minicluster-data/ts-0-root/wals/0b0c756edb80470283cbd69959730681/wal-000000017 (ops 81-85)
I20260812 06:18:51.261370   718 log.cc:1079] T 0b0c756edb80470283cbd69959730681 P 2ab4b95a840940c18330f1b983b856bd: Deleting log segment in path: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515527602152-532-0/minicluster-data/ts-0-root/wals/0b0c756edb80470283cbd69959730681/wal-000000018 (ops 86-90)
I20260812 06:18:51.261410   718 log.cc:1079] T 0b0c756edb80470283cbd69959730681 P 2ab4b95a840940c18330f1b983b856bd: Deleting log segment in path: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515527602152-532-0/minicluster-data/ts-0-root/wals/0b0c756edb80470283cbd69959730681/wal-000000019 (ops 91-95)
I20260812 06:18:51.261451   718 log.cc:1079] T 0b0c756edb80470283cbd69959730681 P 2ab4b95a840940c18330f1b983b856bd: Deleting log segment in path: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515527602152-532-0/minicluster-data/ts-0-root/wals/0b0c756edb80470283cbd69959730681/wal-000000020 (ops 96-100)
I20260812 06:18:51.261492   718 log.cc:1079] T 0b0c756edb80470283cbd69959730681 P 2ab4b95a840940c18330f1b983b856bd: Deleting log segment in path: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515527602152-532-0/minicluster-data/ts-0-root/wals/0b0c756edb80470283cbd69959730681/wal-000000021 (ops 101-104)
I20260812 06:18:51.261529   718 log.cc:1079] T 0b0c756edb80470283cbd69959730681 P 2ab4b95a840940c18330f1b983b856bd: Deleting log segment in path: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515527602152-532-0/minicluster-data/ts-0-root/wals/0b0c756edb80470283cbd69959730681/wal-000000022 (ops 105-109)
I20260812 06:18:51.261567   718 log.cc:1079] T 0b0c756edb80470283cbd69959730681 P 2ab4b95a840940c18330f1b983b856bd: Deleting log segment in path: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515527602152-532-0/minicluster-data/ts-0-root/wals/0b0c756edb80470283cbd69959730681/wal-000000023 (ops 110-114)
I20260812 06:18:51.261608   718 log.cc:1079] T 0b0c756edb80470283cbd69959730681 P 2ab4b95a840940c18330f1b983b856bd: Deleting log segment in path: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515527602152-532-0/minicluster-data/ts-0-root/wals/0b0c756edb80470283cbd69959730681/wal-000000024 (ops 115-118)
I20260812 06:18:51.261648   718 log.cc:1079] T 0b0c756edb80470283cbd69959730681 P 2ab4b95a840940c18330f1b983b856bd: Deleting log segment in path: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515527602152-532-0/minicluster-data/ts-0-root/wals/0b0c756edb80470283cbd69959730681/wal-000000025 (ops 119-123)
I20260812 06:18:51.290632   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: LogGCOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.030s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:18:51.291019   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling UndoDeltaBlockGCOp(0b0c756edb80470283cbd69959730681): 482 bytes on disk
I20260812 06:18:51.291410   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: UndoDeltaBlockGCOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4}
I20260812 06:18:51.291893   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681): perf score=7.149875
I20260812 06:18:51.321676   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.030s	user 0.000s	sys 0.018s Metrics: {"bytes_written":8615324,"delete_count":0,"lbm_write_time_us":8948,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:18:51.322224   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling LogGCOp(0b0c756edb80470283cbd69959730681): free 12017983 bytes of WAL
I20260812 06:18:51.322472   718 log_reader.cc:385] T 0b0c756edb80470283cbd69959730681: removed 1 log segments from log reader
I20260812 06:18:51.322546   718 log.cc:1079] T 0b0c756edb80470283cbd69959730681 P 2ab4b95a840940c18330f1b983b856bd: Deleting log segment in path: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515527602152-532-0/minicluster-data/ts-0-root/wals/0b0c756edb80470283cbd69959730681/wal-000000026 (ops 124-128)
I20260812 06:18:51.325022   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: LogGCOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:18:51.325325   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681): perf score=2.188937
I20260812 06:18:51.335902   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3897,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:51.336359   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling MajorDeltaCompactionOp(0b0c756edb80470283cbd69959730681): perf score=1.000000
I20260812 06:18:51.582825   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: MajorDeltaCompactionOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.246s	user 0.146s	sys 0.101s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32938770,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":249,"lbm_read_time_us":17534,"lbm_reads_lt_1ms":774,"lbm_write_time_us":42817,"lbm_writes_lt_1ms":743,"mutex_wait_us":29,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":49152,"thread_start_us":79,"threads_started":1,"update_count":3500}
I20260812 06:18:51.583580   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681): perf score=18.063937
I20260812 06:18:51.645442   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.062s	user 0.047s	sys 0.008s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":26766,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:51.645960   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling MajorDeltaCompactionOp(0b0c756edb80470283cbd69959730681): perf score=1.000000
I20260812 06:18:51.815691   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: MajorDeltaCompactionOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.170s	user 0.122s	sys 0.047s Metrics: {"cfile_cache_miss":531,"cfile_cache_miss_bytes":24733606,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":560,"lbm_read_time_us":13037,"lbm_reads_lt_1ms":563,"lbm_write_time_us":29881,"lbm_writes_lt_1ms":543,"mutex_wait_us":310,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2500}
I20260812 06:18:51.816277   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681): perf score=14.095187
I20260812 06:18:51.886207   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.070s	user 0.031s	sys 0.035s Metrics: {"bytes_written":16409906,"delete_count":0,"lbm_write_time_us":24671,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:51.886894   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681): perf score=2.188937
I20260812 06:18:51.902508   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.015s	user 0.007s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6189,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:51.902913   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling MajorDeltaCompactionOp(0b0c756edb80470283cbd69959730681): perf score=1.000000
I20260812 06:18:52.095463   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: MajorDeltaCompactionOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.192s	user 0.141s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733728,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":191,"lbm_read_time_us":14602,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33172,"lbm_writes_lt_1ms":543,"mutex_wait_us":3,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2500}
I20260812 06:18:52.096339   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681): perf score=11.118625
I20260812 06:18:52.132025   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.035s	user 0.022s	sys 0.011s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14937,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:52.132771   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681): perf score=2.188937
I20260812 06:18:52.168978   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.036s	user 0.011s	sys 0.015s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6366,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:52.169551   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681): perf score=2.188937
I20260812 06:18:52.181782   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4466,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:52.182341   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling MajorDeltaCompactionOp(0b0c756edb80470283cbd69959730681): perf score=1.000000
I20260812 06:18:52.359522   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: MajorDeltaCompactionOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.177s	user 0.118s	sys 0.057s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733833,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":242,"lbm_read_time_us":13514,"lbm_reads_lt_1ms":573,"lbm_write_time_us":32261,"lbm_writes_lt_1ms":543,"mutex_wait_us":84,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:52.360299   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681): perf score=11.118625
I20260812 06:18:52.403149   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.043s	user 0.026s	sys 0.016s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":19107,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:52.403632   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681): perf score=2.188937
I20260812 06:18:52.415936   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.012s	user 0.002s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4302,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:52.416416   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling MajorDeltaCompactionOp(0b0c756edb80470283cbd69959730681): perf score=1.000000
I20260812 06:18:52.546343   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: MajorDeltaCompactionOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.130s	user 0.081s	sys 0.047s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631305,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":546,"lbm_read_time_us":10819,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24547,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2000}
I20260812 06:18:52.547075   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681): perf score=10.126437
I20260812 06:18:52.583451   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.036s	user 0.022s	sys 0.011s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":15578,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:52.584082   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681): perf score=2.188937
I20260812 06:18:52.600235   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.016s	user 0.011s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6449,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:52.600754   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling MajorDeltaCompactionOp(0b0c756edb80470283cbd69959730681): perf score=1.000000
I20260812 06:18:52.721915   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: MajorDeltaCompactionOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.121s	user 0.100s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631314,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":218,"lbm_read_time_us":8811,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25758,"lbm_writes_lt_1ms":443,"mutex_wait_us":46,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9344,"update_count":2000}
I20260812 06:18:52.722693   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681): perf score=10.126437
I20260812 06:18:52.764101   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.041s	user 0.021s	sys 0.018s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18865,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:52.764683   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681): perf score=2.188937
I20260812 06:18:52.780872   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.016s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6455,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:52.781358   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling FlushMRSOp(0b0c756edb80470283cbd69959730681): perf score=1.000000
I20260812 06:18:52.808041   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: FlushMRSOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.027s	user 0.025s	sys 0.000s Metrics: {"bytes_written":1193505,"cfile_init":1,"dirs.queue_time_us":64,"dirs.run_cpu_time_us":252,"dirs.run_wall_time_us":1142,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1764,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:52.808687   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling LogGCOp(0b0c756edb80470283cbd69959730681): free 121006692 bytes of WAL
I20260812 06:18:52.808907   718 log_reader.cc:385] T 0b0c756edb80470283cbd69959730681: removed 12 log segments from log reader
I20260812 06:18:52.808949   718 log.cc:1079] T 0b0c756edb80470283cbd69959730681 P 2ab4b95a840940c18330f1b983b856bd: Deleting log segment in path: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515527602152-532-0/minicluster-data/ts-0-root/wals/0b0c756edb80470283cbd69959730681/wal-000000027 (ops 129-133)
I20260812 06:18:52.808977   718 log.cc:1079] T 0b0c756edb80470283cbd69959730681 P 2ab4b95a840940c18330f1b983b856bd: Deleting log segment in path: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515527602152-532-0/minicluster-data/ts-0-root/wals/0b0c756edb80470283cbd69959730681/wal-000000028 (ops 134-138)
I20260812 06:18:52.809044   718 log.cc:1079] T 0b0c756edb80470283cbd69959730681 P 2ab4b95a840940c18330f1b983b856bd: Deleting log segment in path: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515527602152-532-0/minicluster-data/ts-0-root/wals/0b0c756edb80470283cbd69959730681/wal-000000029 (ops 139-143)
I20260812 06:18:52.809088   718 log.cc:1079] T 0b0c756edb80470283cbd69959730681 P 2ab4b95a840940c18330f1b983b856bd: Deleting log segment in path: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515527602152-532-0/minicluster-data/ts-0-root/wals/0b0c756edb80470283cbd69959730681/wal-000000030 (ops 144-148)
I20260812 06:18:52.809131   718 log.cc:1079] T 0b0c756edb80470283cbd69959730681 P 2ab4b95a840940c18330f1b983b856bd: Deleting log segment in path: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515527602152-532-0/minicluster-data/ts-0-root/wals/0b0c756edb80470283cbd69959730681/wal-000000031 (ops 149-153)
I20260812 06:18:52.809188   718 log.cc:1079] T 0b0c756edb80470283cbd69959730681 P 2ab4b95a840940c18330f1b983b856bd: Deleting log segment in path: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515527602152-532-0/minicluster-data/ts-0-root/wals/0b0c756edb80470283cbd69959730681/wal-000000032 (ops 154-158)
I20260812 06:18:52.809213   718 log.cc:1079] T 0b0c756edb80470283cbd69959730681 P 2ab4b95a840940c18330f1b983b856bd: Deleting log segment in path: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515527602152-532-0/minicluster-data/ts-0-root/wals/0b0c756edb80470283cbd69959730681/wal-000000033 (ops 159-162)
I20260812 06:18:52.809254   718 log.cc:1079] T 0b0c756edb80470283cbd69959730681 P 2ab4b95a840940c18330f1b983b856bd: Deleting log segment in path: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515527602152-532-0/minicluster-data/ts-0-root/wals/0b0c756edb80470283cbd69959730681/wal-000000034 (ops 163-167)
I20260812 06:18:52.809294   718 log.cc:1079] T 0b0c756edb80470283cbd69959730681 P 2ab4b95a840940c18330f1b983b856bd: Deleting log segment in path: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515527602152-532-0/minicluster-data/ts-0-root/wals/0b0c756edb80470283cbd69959730681/wal-000000035 (ops 168-172)
I20260812 06:18:52.809337   718 log.cc:1079] T 0b0c756edb80470283cbd69959730681 P 2ab4b95a840940c18330f1b983b856bd: Deleting log segment in path: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515527602152-532-0/minicluster-data/ts-0-root/wals/0b0c756edb80470283cbd69959730681/wal-000000036 (ops 173-177)
I20260812 06:18:52.809379   718 log.cc:1079] T 0b0c756edb80470283cbd69959730681 P 2ab4b95a840940c18330f1b983b856bd: Deleting log segment in path: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515527602152-532-0/minicluster-data/ts-0-root/wals/0b0c756edb80470283cbd69959730681/wal-000000037 (ops 178-182)
I20260812 06:18:52.809419   718 log.cc:1079] T 0b0c756edb80470283cbd69959730681 P 2ab4b95a840940c18330f1b983b856bd: Deleting log segment in path: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515527602152-532-0/minicluster-data/ts-0-root/wals/0b0c756edb80470283cbd69959730681/wal-000000038 (ops 183-187)
I20260812 06:18:52.840145   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: LogGCOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.031s	user 0.001s	sys 0.028s Metrics: {}
I20260812 06:18:52.840847   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling UndoDeltaBlockGCOp(0b0c756edb80470283cbd69959730681): 463 bytes on disk
I20260812 06:18:52.841475   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: UndoDeltaBlockGCOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":78,"lbm_reads_lt_1ms":4}
I20260812 06:18:52.842398   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681): perf score=3.181125
I20260812 06:18:52.858695   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.016s	user 0.007s	sys 0.009s Metrics: {"bytes_written":5374418,"delete_count":0,"lbm_write_time_us":6696,"lbm_writes_lt_1ms":134,"reinsert_count":0,"update_count":655}
I20260812 06:18:52.859162   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681): perf score=1.196750
I20260812 06:18:52.870939   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":2830880,"delete_count":0,"lbm_write_time_us":4318,"lbm_writes_lt_1ms":72,"reinsert_count":0,"update_count":345}
I20260812 06:18:52.871539   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling MajorDeltaCompactionOp(0b0c756edb80470283cbd69959730681): perf score=1.000000
I20260812 06:18:53.052692   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: MajorDeltaCompactionOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.181s	user 0.132s	sys 0.048s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836348,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":754,"lbm_read_time_us":12604,"lbm_reads_lt_1ms":674,"lbm_write_time_us":36122,"lbm_writes_lt_1ms":643,"mutex_wait_us":310,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1280,"thread_start_us":78,"threads_started":1,"update_count":3000}
I20260812 06:18:53.053421   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681): perf score=14.095187
I20260812 06:18:53.113497   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.060s	user 0.037s	sys 0.019s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":28209,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:53.114434   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681): perf score=2.188937
I20260812 06:18:53.130187   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: FlushDeltaMemStoresOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.016s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6199,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:53.130703   819 maintenance_manager.cc:419] P 2ab4b95a840940c18330f1b983b856bd: Scheduling MajorDeltaCompactionOp(0b0c756edb80470283cbd69959730681): perf score=1.000000
I20260812 06:18:53.141350   532 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.242s	user 1.850s	sys 0.203s
I20260812 06:18:53.215909   532 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.074s	user 0.002s	sys 0.000s
I20260812 06:18:53.216547   532 tablet_server.cc:179] TabletServer@127.0.133.1:0 shutting down...
I20260812 06:18:53.273286   718 maintenance_manager.cc:643] P 2ab4b95a840940c18330f1b983b856bd: MajorDeltaCompactionOp(0b0c756edb80470283cbd69959730681) complete. Timing: real 0.142s	user 0.113s	sys 0.028s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":766,"lbm_read_time_us":12580,"lbm_reads_lt_1ms":560,"lbm_write_time_us":28843,"lbm_writes_lt_1ms":543,"mutex_wait_us":333,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":27008,"update_count":2500}
I20260812 06:18:53.274075   532 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:53.274569   532 tablet_replica.cc:333] T 0b0c756edb80470283cbd69959730681 P 2ab4b95a840940c18330f1b983b856bd: stopping tablet replica
I20260812 06:18:53.274837   532 raft_consensus.cc:2243] T 0b0c756edb80470283cbd69959730681 P 2ab4b95a840940c18330f1b983b856bd [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:53.275085   532 raft_consensus.cc:2272] T 0b0c756edb80470283cbd69959730681 P 2ab4b95a840940c18330f1b983b856bd [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:53.305490   532 tablet_server.cc:196] TabletServer@127.0.133.1:0 shutdown complete.
I20260812 06:18:53.319115   532 master.cc:562] Master@127.0.133.62:39305 shutting down...
I20260812 06:18:53.323035   532 raft_consensus.cc:2243] T 00000000000000000000000000000000 P a9593c8860c8487ea71ae83002ee581e [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:53.323442   532 raft_consensus.cc:2272] T 00000000000000000000000000000000 P a9593c8860c8487ea71ae83002ee581e [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:53.323560   532 tablet_replica.cc:333] T 00000000000000000000000000000000 P a9593c8860c8487ea71ae83002ee581e: stopping tablet replica
I20260812 06:18:53.336417   532 master.cc:584] Master@127.0.133.62:39305 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5820 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:53.433163   532 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.0.133.62:37075
I20260812 06:18:53.433656   532 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:53.436195   880 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:53.436190   878 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:18:53.436189   875 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:18:53.436321   532 server_base.cc:1061] running on GCE node
I20260812 06:18:53.436591   532 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:53.436635   532 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:53.436650   532 hybrid_clock.cc:648] HybridClock initialized: now 1786515533436650 us; error 0 us; skew 500 ppm
I20260812 06:18:53.437584   532 webserver.cc:533] Webserver started at http://127.0.133.62:36109/ using document root <none> and password file <none>
I20260812 06:18:53.437731   532 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:53.437769   532 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:53.437909   532 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:53.438401   532 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515527602152-532-0/minicluster-data/master-0-root/instance:
uuid: "04b4ef270c5145a09b4514e41578668c"
format_stamp: "Formatted at 2026-08-12 06:18:53 on dist-test-slave-7nm7"
I20260812 06:18:53.439910   532 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:53.440836   888 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:53.441120   532 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:53.441186   532 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515527602152-532-0/minicluster-data/master-0-root
uuid: "04b4ef270c5145a09b4514e41578668c"
format_stamp: "Formatted at 2026-08-12 06:18:53 on dist-test-slave-7nm7"
I20260812 06:18:53.441241   532 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515527602152-532-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515527602152-532-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515527602152-532-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:53.452756   532 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:53.453182   532 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:53.457032   532 rpc_server.cc:307] RPC server started. Bound to: 127.0.133.62:37075
I20260812 06:18:53.459488   968 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.0.133.62:37075 every 8 connection(s)
I20260812 06:18:53.462776   969 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:53.469789   969 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 04b4ef270c5145a09b4514e41578668c: Bootstrap starting.
I20260812 06:18:53.470695   969 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 04b4ef270c5145a09b4514e41578668c: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:53.471823   969 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 04b4ef270c5145a09b4514e41578668c: No bootstrap required, opened a new log
I20260812 06:18:53.472240   969 raft_consensus.cc:359] T 00000000000000000000000000000000 P 04b4ef270c5145a09b4514e41578668c [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "04b4ef270c5145a09b4514e41578668c" member_type: VOTER }
I20260812 06:18:53.472337   969 raft_consensus.cc:385] T 00000000000000000000000000000000 P 04b4ef270c5145a09b4514e41578668c [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:53.472364   969 raft_consensus.cc:740] T 00000000000000000000000000000000 P 04b4ef270c5145a09b4514e41578668c [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 04b4ef270c5145a09b4514e41578668c, State: Initialized, Role: FOLLOWER
I20260812 06:18:53.472541   969 consensus_queue.cc:260] T 00000000000000000000000000000000 P 04b4ef270c5145a09b4514e41578668c [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: "04b4ef270c5145a09b4514e41578668c" member_type: VOTER }
I20260812 06:18:53.472647   969 raft_consensus.cc:399] T 00000000000000000000000000000000 P 04b4ef270c5145a09b4514e41578668c [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:53.472677   969 raft_consensus.cc:493] T 00000000000000000000000000000000 P 04b4ef270c5145a09b4514e41578668c [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:53.472719   969 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 04b4ef270c5145a09b4514e41578668c [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:53.473389   969 raft_consensus.cc:515] T 00000000000000000000000000000000 P 04b4ef270c5145a09b4514e41578668c [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "04b4ef270c5145a09b4514e41578668c" member_type: VOTER }
I20260812 06:18:53.473516   969 leader_election.cc:304] T 00000000000000000000000000000000 P 04b4ef270c5145a09b4514e41578668c [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: 04b4ef270c5145a09b4514e41578668c; no voters: 
I20260812 06:18:53.473676   969 leader_election.cc:290] T 00000000000000000000000000000000 P 04b4ef270c5145a09b4514e41578668c [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:53.473816   974 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 04b4ef270c5145a09b4514e41578668c [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:53.474035   974 raft_consensus.cc:697] T 00000000000000000000000000000000 P 04b4ef270c5145a09b4514e41578668c [term 1 LEADER]: Becoming Leader. State: Replica: 04b4ef270c5145a09b4514e41578668c, State: Running, Role: LEADER
I20260812 06:18:53.474231   969 sys_catalog.cc:565] T 00000000000000000000000000000000 P 04b4ef270c5145a09b4514e41578668c [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:53.474212   974 consensus_queue.cc:237] T 00000000000000000000000000000000 P 04b4ef270c5145a09b4514e41578668c [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: "04b4ef270c5145a09b4514e41578668c" member_type: VOTER }
I20260812 06:18:53.474722   977 sys_catalog.cc:455] T 00000000000000000000000000000000 P 04b4ef270c5145a09b4514e41578668c [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "04b4ef270c5145a09b4514e41578668c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "04b4ef270c5145a09b4514e41578668c" member_type: VOTER } }
I20260812 06:18:53.474772   978 sys_catalog.cc:455] T 00000000000000000000000000000000 P 04b4ef270c5145a09b4514e41578668c [sys.catalog]: SysCatalogTable state changed. Reason: New leader 04b4ef270c5145a09b4514e41578668c. Latest consensus state: current_term: 1 leader_uuid: "04b4ef270c5145a09b4514e41578668c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "04b4ef270c5145a09b4514e41578668c" member_type: VOTER } }
I20260812 06:18:53.474892   977 sys_catalog.cc:458] T 00000000000000000000000000000000 P 04b4ef270c5145a09b4514e41578668c [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:53.474977   978 sys_catalog.cc:458] T 00000000000000000000000000000000 P 04b4ef270c5145a09b4514e41578668c [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:53.475487   983 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:53.476394   983 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:53.476720   532 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:53.478163   983 catalog_manager.cc:1383] Generated new cluster ID: 932602524da145cebb3ad2b188bfb516
I20260812 06:18:53.478224   983 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:53.515128   983 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:53.515769   983 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:53.521657   983 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 04b4ef270c5145a09b4514e41578668c: Generated new TSK 0
I20260812 06:18:53.521883   983 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:53.541481   532 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:53.544219  1007 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:53.544502  1003 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:53.544636  1004 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:53.544763   532 server_base.cc:1061] running on GCE node
I20260812 06:18:53.545068   532 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:53.545133   532 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:53.545154   532 hybrid_clock.cc:648] HybridClock initialized: now 1786515533545151 us; error 0 us; skew 500 ppm
I20260812 06:18:53.546142   532 webserver.cc:533] Webserver started at http://127.0.133.1:33421/ using document root <none> and password file <none>
I20260812 06:18:53.546382   532 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:53.546437   532 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:53.546494   532 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:53.546852   532 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515527602152-532-0/minicluster-data/ts-0-root/instance:
uuid: "ff6a3e6addb54ec992477a7e4de1e565"
format_stamp: "Formatted at 2026-08-12 06:18:53 on dist-test-slave-7nm7"
I20260812 06:18:53.548628   532 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:53.549942  1019 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:53.550441   532 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:53.550527   532 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515527602152-532-0/minicluster-data/ts-0-root
uuid: "ff6a3e6addb54ec992477a7e4de1e565"
format_stamp: "Formatted at 2026-08-12 06:18:53 on dist-test-slave-7nm7"
I20260812 06:18:53.550592   532 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515527602152-532-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515527602152-532-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515527602152-532-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:53.560297   532 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:53.560709   532 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:53.560978   532 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:53.561491   532 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:53.561539   532 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:53.561573   532 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:53.561587   532 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:53.566895   532 rpc_server.cc:307] RPC server started. Bound to: 127.0.133.1:44855
I20260812 06:18:53.566932  1118 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.0.133.1:44855 every 8 connection(s)
I20260812 06:18:53.579022  1120 heartbeater.cc:344] Connected to a master server at 127.0.133.62:37075
I20260812 06:18:53.579229  1120 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:53.579532  1120 heartbeater.cc:507] Master 127.0.133.62:37075 requested a full tablet report, sending...
I20260812 06:18:53.580466   915 ts_manager.cc:194] Registered new tserver with Master: ff6a3e6addb54ec992477a7e4de1e565 (127.0.133.1:44855)
I20260812 06:18:53.580941   532 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.013576747s
I20260812 06:18:53.581604   915 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:42030
I20260812 06:18:53.590018   915 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:42044:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:53.602177  1060 tablet_service.cc:1511] Processing CreateTablet for tablet 0429753b77704850a6698673a6669bfc (DEFAULT_TABLE table=heavy-update-compaction-test [id=c5253b536aa24b2cb57744bb9f0ed96c]), partition=
I20260812 06:18:53.602556  1060 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 0429753b77704850a6698673a6669bfc. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:53.604970  1143 tablet_bootstrap.cc:492] T 0429753b77704850a6698673a6669bfc P ff6a3e6addb54ec992477a7e4de1e565: Bootstrap starting.
I20260812 06:18:53.605914  1143 tablet_bootstrap.cc:654] T 0429753b77704850a6698673a6669bfc P ff6a3e6addb54ec992477a7e4de1e565: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:53.607229  1143 tablet_bootstrap.cc:492] T 0429753b77704850a6698673a6669bfc P ff6a3e6addb54ec992477a7e4de1e565: No bootstrap required, opened a new log
I20260812 06:18:53.607338  1143 ts_tablet_manager.cc:1403] T 0429753b77704850a6698673a6669bfc P ff6a3e6addb54ec992477a7e4de1e565: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:53.607806  1143 raft_consensus.cc:359] T 0429753b77704850a6698673a6669bfc P ff6a3e6addb54ec992477a7e4de1e565 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ff6a3e6addb54ec992477a7e4de1e565" member_type: VOTER last_known_addr { host: "127.0.133.1" port: 44855 } }
I20260812 06:18:53.607899  1143 raft_consensus.cc:385] T 0429753b77704850a6698673a6669bfc P ff6a3e6addb54ec992477a7e4de1e565 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:53.607923  1143 raft_consensus.cc:740] T 0429753b77704850a6698673a6669bfc P ff6a3e6addb54ec992477a7e4de1e565 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: ff6a3e6addb54ec992477a7e4de1e565, State: Initialized, Role: FOLLOWER
I20260812 06:18:53.608060  1143 consensus_queue.cc:260] T 0429753b77704850a6698673a6669bfc P ff6a3e6addb54ec992477a7e4de1e565 [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: "ff6a3e6addb54ec992477a7e4de1e565" member_type: VOTER last_known_addr { host: "127.0.133.1" port: 44855 } }
I20260812 06:18:53.608410  1143 raft_consensus.cc:399] T 0429753b77704850a6698673a6669bfc P ff6a3e6addb54ec992477a7e4de1e565 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:53.608464  1143 raft_consensus.cc:493] T 0429753b77704850a6698673a6669bfc P ff6a3e6addb54ec992477a7e4de1e565 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:53.608518  1143 raft_consensus.cc:3060] T 0429753b77704850a6698673a6669bfc P ff6a3e6addb54ec992477a7e4de1e565 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:53.609637  1143 raft_consensus.cc:515] T 0429753b77704850a6698673a6669bfc P ff6a3e6addb54ec992477a7e4de1e565 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ff6a3e6addb54ec992477a7e4de1e565" member_type: VOTER last_known_addr { host: "127.0.133.1" port: 44855 } }
I20260812 06:18:53.609790  1143 leader_election.cc:304] T 0429753b77704850a6698673a6669bfc P ff6a3e6addb54ec992477a7e4de1e565 [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: ff6a3e6addb54ec992477a7e4de1e565; no voters: 
I20260812 06:18:53.609954  1143 leader_election.cc:290] T 0429753b77704850a6698673a6669bfc P ff6a3e6addb54ec992477a7e4de1e565 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:53.610147  1147 raft_consensus.cc:2804] T 0429753b77704850a6698673a6669bfc P ff6a3e6addb54ec992477a7e4de1e565 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:53.610354  1143 ts_tablet_manager.cc:1434] T 0429753b77704850a6698673a6669bfc P ff6a3e6addb54ec992477a7e4de1e565: Time spent starting tablet: real 0.003s	user 0.004s	sys 0.000s
I20260812 06:18:53.610355  1120 heartbeater.cc:499] Master 127.0.133.62:37075 was elected leader, sending a full tablet report...
I20260812 06:18:53.610484  1147 raft_consensus.cc:697] T 0429753b77704850a6698673a6669bfc P ff6a3e6addb54ec992477a7e4de1e565 [term 1 LEADER]: Becoming Leader. State: Replica: ff6a3e6addb54ec992477a7e4de1e565, State: Running, Role: LEADER
I20260812 06:18:53.610662  1147 consensus_queue.cc:237] T 0429753b77704850a6698673a6669bfc P ff6a3e6addb54ec992477a7e4de1e565 [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: "ff6a3e6addb54ec992477a7e4de1e565" member_type: VOTER last_known_addr { host: "127.0.133.1" port: 44855 } }
I20260812 06:18:53.612169   915 catalog_manager.cc:5719] T 0429753b77704850a6698673a6669bfc P ff6a3e6addb54ec992477a7e4de1e565 reported cstate change: term changed from 0 to 1, leader changed from <none> to ff6a3e6addb54ec992477a7e4de1e565 (127.0.133.1). New cstate: current_term: 1 leader_uuid: "ff6a3e6addb54ec992477a7e4de1e565" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ff6a3e6addb54ec992477a7e4de1e565" member_type: VOTER last_known_addr { host: "127.0.133.1" port: 44855 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:53.674096   532 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.056s	user 0.015s	sys 0.008s
I20260812 06:18:53.817900  1121 maintenance_manager.cc:419] P ff6a3e6addb54ec992477a7e4de1e565: Scheduling FlushMRSOp(0429753b77704850a6698673a6669bfc): perf score=19.054940
I20260812 06:18:53.982708  1024 maintenance_manager.cc:643] P ff6a3e6addb54ec992477a7e4de1e565: FlushMRSOp(0429753b77704850a6698673a6669bfc) complete. Timing: real 0.164s	user 0.124s	sys 0.039s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":84,"dirs.run_cpu_time_us":208,"dirs.run_wall_time_us":914,"drs_written":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4,"lbm_write_time_us":42142,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:18:53.983392  1121 maintenance_manager.cc:419] P ff6a3e6addb54ec992477a7e4de1e565: Scheduling LogGCOp(0429753b77704850a6698673a6669bfc): free 20743831 bytes of WAL
I20260812 06:18:53.983626  1024 log_reader.cc:385] T 0429753b77704850a6698673a6669bfc: removed 2 log segments from log reader
I20260812 06:18:53.983675  1024 log.cc:1079] T 0429753b77704850a6698673a6669bfc P ff6a3e6addb54ec992477a7e4de1e565: Deleting log segment in path: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515527602152-532-0/minicluster-data/ts-0-root/wals/0429753b77704850a6698673a6669bfc/wal-000000001 (ops 1-6)
I20260812 06:18:53.983733  1024 log.cc:1079] T 0429753b77704850a6698673a6669bfc P ff6a3e6addb54ec992477a7e4de1e565: Deleting log segment in path: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515527602152-532-0/minicluster-data/ts-0-root/wals/0429753b77704850a6698673a6669bfc/wal-000000002 (ops 7-11)
I20260812 06:18:53.988420  1024 maintenance_manager.cc:643] P ff6a3e6addb54ec992477a7e4de1e565: LogGCOp(0429753b77704850a6698673a6669bfc) complete. Timing: real 0.005s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:18:53.988759  1121 maintenance_manager.cc:419] P ff6a3e6addb54ec992477a7e4de1e565: Scheduling FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc): perf score=2.188937
I20260812 06:18:54.002959  1024 maintenance_manager.cc:643] P ff6a3e6addb54ec992477a7e4de1e565: FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc) complete. Timing: real 0.014s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5241,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:54.003603  1121 maintenance_manager.cc:419] P ff6a3e6addb54ec992477a7e4de1e565: Scheduling UndoDeltaBlockGCOp(0429753b77704850a6698673a6669bfc): 16411392 bytes on disk
I20260812 06:18:54.004181  1024 maintenance_manager.cc:643] P ff6a3e6addb54ec992477a7e4de1e565: UndoDeltaBlockGCOp(0429753b77704850a6698673a6669bfc) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":82,"lbm_reads_lt_1ms":4}
I20260812 06:18:54.004833  1121 maintenance_manager.cc:419] P ff6a3e6addb54ec992477a7e4de1e565: Scheduling MajorDeltaCompactionOp(0429753b77704850a6698673a6669bfc): perf score=1.000000
I20260812 06:18:54.155524  1024 maintenance_manager.cc:643] P ff6a3e6addb54ec992477a7e4de1e565: MajorDeltaCompactionOp(0429753b77704850a6698673a6669bfc) complete. Timing: real 0.151s	user 0.109s	sys 0.039s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":608,"lbm_read_time_us":12061,"lbm_reads_lt_1ms":460,"lbm_write_time_us":25441,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":318,"threads_started":5,"update_count":2000}
I20260812 06:18:54.156060  1121 maintenance_manager.cc:419] P ff6a3e6addb54ec992477a7e4de1e565: Scheduling FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc): perf score=11.118625
I20260812 06:18:54.212297  1024 maintenance_manager.cc:643] P ff6a3e6addb54ec992477a7e4de1e565: FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc) complete. Timing: real 0.056s	user 0.034s	sys 0.019s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":18933,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:54.212924  1121 maintenance_manager.cc:419] P ff6a3e6addb54ec992477a7e4de1e565: Scheduling FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc): perf score=2.188937
I20260812 06:18:54.230034  1024 maintenance_manager.cc:643] P ff6a3e6addb54ec992477a7e4de1e565: FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc) complete. Timing: real 0.017s	user 0.005s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5401,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:54.230597  1121 maintenance_manager.cc:419] P ff6a3e6addb54ec992477a7e4de1e565: Scheduling MajorDeltaCompactionOp(0429753b77704850a6698673a6669bfc): perf score=1.000000
I20260812 06:18:54.403852  1024 maintenance_manager.cc:643] P ff6a3e6addb54ec992477a7e4de1e565: MajorDeltaCompactionOp(0429753b77704850a6698673a6669bfc) complete. Timing: real 0.173s	user 0.102s	sys 0.059s 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":149,"lbm_read_time_us":12660,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27691,"lbm_writes_lt_1ms":443,"mutex_wait_us":45,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":384,"update_count":2000}
I20260812 06:18:54.404652  1121 maintenance_manager.cc:419] P ff6a3e6addb54ec992477a7e4de1e565: Scheduling FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc): perf score=14.095187
I20260812 06:18:54.460464  1024 maintenance_manager.cc:643] P ff6a3e6addb54ec992477a7e4de1e565: FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc) complete. Timing: real 0.056s	user 0.033s	sys 0.016s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23710,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:54.460896  1121 maintenance_manager.cc:419] P ff6a3e6addb54ec992477a7e4de1e565: Scheduling FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc): perf score=2.188937
I20260812 06:18:54.473770  1024 maintenance_manager.cc:643] P ff6a3e6addb54ec992477a7e4de1e565: FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc) complete. Timing: real 0.013s	user 0.001s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4367,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:54.474421  1121 maintenance_manager.cc:419] P ff6a3e6addb54ec992477a7e4de1e565: Scheduling MajorDeltaCompactionOp(0429753b77704850a6698673a6669bfc): perf score=1.000000
I20260812 06:18:54.669317  1024 maintenance_manager.cc:643] P ff6a3e6addb54ec992477a7e4de1e565: MajorDeltaCompactionOp(0429753b77704850a6698673a6669bfc) complete. Timing: real 0.195s	user 0.125s	sys 0.054s 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":299,"lbm_read_time_us":13101,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31969,"lbm_writes_lt_1ms":543,"mutex_wait_us":47,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13440,"update_count":2500}
I20260812 06:18:54.669998  1121 maintenance_manager.cc:419] P ff6a3e6addb54ec992477a7e4de1e565: Scheduling FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc): perf score=14.095187
I20260812 06:18:54.726127  1024 maintenance_manager.cc:643] P ff6a3e6addb54ec992477a7e4de1e565: FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc) complete. Timing: real 0.056s	user 0.019s	sys 0.032s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":25292,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:54.726619  1121 maintenance_manager.cc:419] P ff6a3e6addb54ec992477a7e4de1e565: Scheduling FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc): perf score=2.188937
I20260812 06:18:54.738730  1024 maintenance_manager.cc:643] P ff6a3e6addb54ec992477a7e4de1e565: FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4384,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:54.739378  1121 maintenance_manager.cc:419] P ff6a3e6addb54ec992477a7e4de1e565: Scheduling MajorDeltaCompactionOp(0429753b77704850a6698673a6669bfc): perf score=1.000000
I20260812 06:18:54.891943  1024 maintenance_manager.cc:643] P ff6a3e6addb54ec992477a7e4de1e565: MajorDeltaCompactionOp(0429753b77704850a6698673a6669bfc) complete. Timing: real 0.152s	user 0.099s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":145,"lbm_read_time_us":11659,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31054,"lbm_writes_lt_1ms":543,"mutex_wait_us":21,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3840,"update_count":2500}
I20260812 06:18:54.893445  1121 maintenance_manager.cc:419] P ff6a3e6addb54ec992477a7e4de1e565: Scheduling FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc): perf score=14.095187
I20260812 06:18:54.946206  1024 maintenance_manager.cc:643] P ff6a3e6addb54ec992477a7e4de1e565: FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc) complete. Timing: real 0.053s	user 0.030s	sys 0.019s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22552,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:54.946797  1121 maintenance_manager.cc:419] P ff6a3e6addb54ec992477a7e4de1e565: Scheduling FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc): perf score=2.188937
I20260812 06:18:54.960677  1024 maintenance_manager.cc:643] P ff6a3e6addb54ec992477a7e4de1e565: FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5439,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:54.961148  1121 maintenance_manager.cc:419] P ff6a3e6addb54ec992477a7e4de1e565: Scheduling MajorDeltaCompactionOp(0429753b77704850a6698673a6669bfc): perf score=1.000000
I20260812 06:18:55.130406  1024 maintenance_manager.cc:643] P ff6a3e6addb54ec992477a7e4de1e565: MajorDeltaCompactionOp(0429753b77704850a6698673a6669bfc) complete. Timing: real 0.169s	user 0.137s	sys 0.024s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":628,"lbm_read_time_us":11687,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33074,"lbm_writes_lt_1ms":543,"mutex_wait_us":43,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9472,"update_count":2500}
I20260812 06:18:55.131042  1121 maintenance_manager.cc:419] P ff6a3e6addb54ec992477a7e4de1e565: Scheduling FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc): perf score=14.095187
I20260812 06:18:55.182778  1024 maintenance_manager.cc:643] P ff6a3e6addb54ec992477a7e4de1e565: FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc) complete. Timing: real 0.052s	user 0.021s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18670,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:55.183320  1121 maintenance_manager.cc:419] P ff6a3e6addb54ec992477a7e4de1e565: Scheduling FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc): perf score=2.188937
I20260812 06:18:55.196317  1024 maintenance_manager.cc:643] P ff6a3e6addb54ec992477a7e4de1e565: FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc) complete. Timing: real 0.013s	user 0.001s	sys 0.010s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4806,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:55.197084  1121 maintenance_manager.cc:419] P ff6a3e6addb54ec992477a7e4de1e565: Scheduling FlushMRSOp(0429753b77704850a6698673a6669bfc): perf score=1.000000
I20260812 06:18:55.224700  1024 maintenance_manager.cc:643] P ff6a3e6addb54ec992477a7e4de1e565: FlushMRSOp(0429753b77704850a6698673a6669bfc) complete. Timing: real 0.027s	user 0.018s	sys 0.008s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":79,"dirs.run_cpu_time_us":276,"dirs.run_wall_time_us":1283,"drs_written":1,"lbm_read_time_us":105,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2229,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:55.225414  1121 maintenance_manager.cc:419] P ff6a3e6addb54ec992477a7e4de1e565: Scheduling LogGCOp(0429753b77704850a6698673a6669bfc): free 112239359 bytes of WAL
I20260812 06:18:55.225649  1024 log_reader.cc:385] T 0429753b77704850a6698673a6669bfc: removed 11 log segments from log reader
I20260812 06:18:55.225713  1024 log.cc:1079] T 0429753b77704850a6698673a6669bfc P ff6a3e6addb54ec992477a7e4de1e565: Deleting log segment in path: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515527602152-532-0/minicluster-data/ts-0-root/wals/0429753b77704850a6698673a6669bfc/wal-000000003 (ops 12-16)
I20260812 06:18:55.225766  1024 log.cc:1079] T 0429753b77704850a6698673a6669bfc P ff6a3e6addb54ec992477a7e4de1e565: Deleting log segment in path: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515527602152-532-0/minicluster-data/ts-0-root/wals/0429753b77704850a6698673a6669bfc/wal-000000004 (ops 17-21)
I20260812 06:18:55.225826  1024 log.cc:1079] T 0429753b77704850a6698673a6669bfc P ff6a3e6addb54ec992477a7e4de1e565: Deleting log segment in path: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515527602152-532-0/minicluster-data/ts-0-root/wals/0429753b77704850a6698673a6669bfc/wal-000000005 (ops 22-26)
I20260812 06:18:55.225867  1024 log.cc:1079] T 0429753b77704850a6698673a6669bfc P ff6a3e6addb54ec992477a7e4de1e565: Deleting log segment in path: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515527602152-532-0/minicluster-data/ts-0-root/wals/0429753b77704850a6698673a6669bfc/wal-000000006 (ops 27-31)
I20260812 06:18:55.225922  1024 log.cc:1079] T 0429753b77704850a6698673a6669bfc P ff6a3e6addb54ec992477a7e4de1e565: Deleting log segment in path: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515527602152-532-0/minicluster-data/ts-0-root/wals/0429753b77704850a6698673a6669bfc/wal-000000007 (ops 32-36)
I20260812 06:18:55.225963  1024 log.cc:1079] T 0429753b77704850a6698673a6669bfc P ff6a3e6addb54ec992477a7e4de1e565: Deleting log segment in path: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515527602152-532-0/minicluster-data/ts-0-root/wals/0429753b77704850a6698673a6669bfc/wal-000000008 (ops 37-41)
I20260812 06:18:55.225997  1024 log.cc:1079] T 0429753b77704850a6698673a6669bfc P ff6a3e6addb54ec992477a7e4de1e565: Deleting log segment in path: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515527602152-532-0/minicluster-data/ts-0-root/wals/0429753b77704850a6698673a6669bfc/wal-000000009 (ops 42-46)
I20260812 06:18:55.226037  1024 log.cc:1079] T 0429753b77704850a6698673a6669bfc P ff6a3e6addb54ec992477a7e4de1e565: Deleting log segment in path: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515527602152-532-0/minicluster-data/ts-0-root/wals/0429753b77704850a6698673a6669bfc/wal-000000010 (ops 47-50)
I20260812 06:18:55.226073  1024 log.cc:1079] T 0429753b77704850a6698673a6669bfc P ff6a3e6addb54ec992477a7e4de1e565: Deleting log segment in path: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515527602152-532-0/minicluster-data/ts-0-root/wals/0429753b77704850a6698673a6669bfc/wal-000000011 (ops 51-55)
I20260812 06:18:55.226111  1024 log.cc:1079] T 0429753b77704850a6698673a6669bfc P ff6a3e6addb54ec992477a7e4de1e565: Deleting log segment in path: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515527602152-532-0/minicluster-data/ts-0-root/wals/0429753b77704850a6698673a6669bfc/wal-000000012 (ops 56-60)
I20260812 06:18:55.226148  1024 log.cc:1079] T 0429753b77704850a6698673a6669bfc P ff6a3e6addb54ec992477a7e4de1e565: Deleting log segment in path: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515527602152-532-0/minicluster-data/ts-0-root/wals/0429753b77704850a6698673a6669bfc/wal-000000013 (ops 61-65)
I20260812 06:18:55.253561  1024 maintenance_manager.cc:643] P ff6a3e6addb54ec992477a7e4de1e565: LogGCOp(0429753b77704850a6698673a6669bfc) complete. Timing: real 0.028s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:18:55.253958  1121 maintenance_manager.cc:419] P ff6a3e6addb54ec992477a7e4de1e565: Scheduling FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc): perf score=4.173312
I20260812 06:18:55.269538  1024 maintenance_manager.cc:643] P ff6a3e6addb54ec992477a7e4de1e565: FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc) complete. Timing: real 0.015s	user 0.002s	sys 0.011s Metrics: {"bytes_written":6030801,"delete_count":0,"lbm_write_time_us":6717,"lbm_writes_lt_1ms":150,"reinsert_count":0,"update_count":735}
I20260812 06:18:55.270015  1121 maintenance_manager.cc:419] P ff6a3e6addb54ec992477a7e4de1e565: Scheduling FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc): perf score=1.196750
I20260812 06:18:55.279446  1024 maintenance_manager.cc:643] P ff6a3e6addb54ec992477a7e4de1e565: FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":2174479,"delete_count":0,"lbm_write_time_us":3462,"lbm_writes_lt_1ms":56,"reinsert_count":0,"update_count":265}
I20260812 06:18:55.279937  1121 maintenance_manager.cc:419] P ff6a3e6addb54ec992477a7e4de1e565: Scheduling MajorDeltaCompactionOp(0429753b77704850a6698673a6669bfc): perf score=1.000000
I20260812 06:18:55.489532  1024 maintenance_manager.cc:643] P ff6a3e6addb54ec992477a7e4de1e565: MajorDeltaCompactionOp(0429753b77704850a6698673a6669bfc) complete. Timing: real 0.209s	user 0.150s	sys 0.047s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979706,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":516,"lbm_read_time_us":13636,"lbm_reads_lt_1ms":766,"lbm_write_time_us":43786,"lbm_writes_lt_1ms":743,"mutex_wait_us":21,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":7168,"thread_start_us":163,"threads_started":1,"update_count":3500}
I20260812 06:18:55.490304  1121 maintenance_manager.cc:419] P ff6a3e6addb54ec992477a7e4de1e565: Scheduling FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc): perf score=18.063937
I20260812 06:18:55.563501  1024 maintenance_manager.cc:643] P ff6a3e6addb54ec992477a7e4de1e565: FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc) complete. Timing: real 0.073s	user 0.031s	sys 0.040s Metrics: {"bytes_written":20512320,"delete_count":0,"lbm_write_time_us":32931,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:55.563980  1121 maintenance_manager.cc:419] P ff6a3e6addb54ec992477a7e4de1e565: Scheduling FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc): perf score=3.181125
I20260812 06:18:55.587862  1024 maintenance_manager.cc:643] P ff6a3e6addb54ec992477a7e4de1e565: FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc) complete. Timing: real 0.024s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4430855,"delete_count":0,"lbm_write_time_us":5960,"lbm_writes_lt_1ms":111,"reinsert_count":0,"update_count":540}
I20260812 06:18:55.588366  1121 maintenance_manager.cc:419] P ff6a3e6addb54ec992477a7e4de1e565: Scheduling UndoDeltaBlockGCOp(0429753b77704850a6698673a6669bfc): 447 bytes on disk
I20260812 06:18:55.588792  1024 maintenance_manager.cc:643] P ff6a3e6addb54ec992477a7e4de1e565: UndoDeltaBlockGCOp(0429753b77704850a6698673a6669bfc) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4}
I20260812 06:18:55.589334  1121 maintenance_manager.cc:419] P ff6a3e6addb54ec992477a7e4de1e565: Scheduling FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc): perf score=2.188937
I20260812 06:18:55.601490  1024 maintenance_manager.cc:643] P ff6a3e6addb54ec992477a7e4de1e565: FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc) complete. Timing: real 0.012s	user 0.003s	sys 0.007s Metrics: {"bytes_written":3774459,"delete_count":0,"lbm_write_time_us":4247,"lbm_writes_lt_1ms":95,"reinsert_count":0,"update_count":460}
I20260812 06:18:55.601974  1121 maintenance_manager.cc:419] P ff6a3e6addb54ec992477a7e4de1e565: Scheduling MajorDeltaCompactionOp(0429753b77704850a6698673a6669bfc): perf score=1.000000
I20260812 06:18:55.801931  1024 maintenance_manager.cc:643] P ff6a3e6addb54ec992477a7e4de1e565: MajorDeltaCompactionOp(0429753b77704850a6698673a6669bfc) complete. Timing: real 0.200s	user 0.148s	sys 0.052s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":32979634,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":202,"lbm_read_time_us":17177,"lbm_reads_lt_1ms":773,"lbm_write_time_us":43581,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":3500}
I20260812 06:18:55.802862  1121 maintenance_manager.cc:419] P ff6a3e6addb54ec992477a7e4de1e565: Scheduling FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc): perf score=14.095187
I20260812 06:18:55.857961  1024 maintenance_manager.cc:643] P ff6a3e6addb54ec992477a7e4de1e565: FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc) complete. Timing: real 0.055s	user 0.037s	sys 0.015s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23329,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:55.858867  1121 maintenance_manager.cc:419] P ff6a3e6addb54ec992477a7e4de1e565: Scheduling FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc): perf score=3.181125
I20260812 06:18:55.872509  1024 maintenance_manager.cc:643] P ff6a3e6addb54ec992477a7e4de1e565: FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc) complete. Timing: real 0.013s	user 0.004s	sys 0.005s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":4644,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:55.872965  1121 maintenance_manager.cc:419] P ff6a3e6addb54ec992477a7e4de1e565: Scheduling FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc): perf score=2.188937
I20260812 06:18:55.883502  1024 maintenance_manager.cc:643] P ff6a3e6addb54ec992477a7e4de1e565: FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3952,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:55.884162  1121 maintenance_manager.cc:419] P ff6a3e6addb54ec992477a7e4de1e565: Scheduling MajorDeltaCompactionOp(0429753b77704850a6698673a6669bfc): perf score=1.000000
I20260812 06:18:56.063015  1024 maintenance_manager.cc:643] P ff6a3e6addb54ec992477a7e4de1e565: MajorDeltaCompactionOp(0429753b77704850a6698673a6669bfc) complete. Timing: real 0.179s	user 0.131s	sys 0.044s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877209,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":690,"lbm_read_time_us":12277,"lbm_reads_lt_1ms":673,"lbm_write_time_us":40403,"lbm_writes_lt_1ms":643,"mutex_wait_us":370,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":7936,"update_count":3000}
I20260812 06:18:56.063547  1121 maintenance_manager.cc:419] P ff6a3e6addb54ec992477a7e4de1e565: Scheduling FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc): perf score=14.095187
I20260812 06:18:56.126015  1024 maintenance_manager.cc:643] P ff6a3e6addb54ec992477a7e4de1e565: FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc) complete. Timing: real 0.062s	user 0.034s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":28330,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:56.126478  1121 maintenance_manager.cc:419] P ff6a3e6addb54ec992477a7e4de1e565: Scheduling FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc): perf score=2.188937
I20260812 06:18:56.139902  1024 maintenance_manager.cc:643] P ff6a3e6addb54ec992477a7e4de1e565: FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc) complete. Timing: real 0.013s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5165,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:56.140537  1121 maintenance_manager.cc:419] P ff6a3e6addb54ec992477a7e4de1e565: Scheduling MajorDeltaCompactionOp(0429753b77704850a6698673a6669bfc): perf score=1.000000
I20260812 06:18:56.349666  1024 maintenance_manager.cc:643] P ff6a3e6addb54ec992477a7e4de1e565: MajorDeltaCompactionOp(0429753b77704850a6698673a6669bfc) complete. Timing: real 0.209s	user 0.136s	sys 0.059s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1007,"lbm_read_time_us":10174,"lbm_reads_lt_1ms":572,"lbm_write_time_us":38431,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":542,"mutex_wait_us":387,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2500}
I20260812 06:18:56.350530  1121 maintenance_manager.cc:419] P ff6a3e6addb54ec992477a7e4de1e565: Scheduling FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc): perf score=18.063937
I20260812 06:18:56.451479  1024 maintenance_manager.cc:643] P ff6a3e6addb54ec992477a7e4de1e565: FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc) complete. Timing: real 0.101s	user 0.068s	sys 0.016s Metrics: {"bytes_written":20512318,"delete_count":0,"lbm_write_time_us":39155,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":501,"reinsert_count":0,"update_count":2500}
I20260812 06:18:56.452035  1121 maintenance_manager.cc:419] P ff6a3e6addb54ec992477a7e4de1e565: Scheduling FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc): perf score=6.157687
I20260812 06:18:56.481366  1024 maintenance_manager.cc:643] P ff6a3e6addb54ec992477a7e4de1e565: FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc) complete. Timing: real 0.029s	user 0.017s	sys 0.009s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":12531,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:18:56.482064  1121 maintenance_manager.cc:419] P ff6a3e6addb54ec992477a7e4de1e565: Scheduling FlushMRSOp(0429753b77704850a6698673a6669bfc): perf score=1.000000
I20260812 06:18:56.512923  1024 maintenance_manager.cc:643] P ff6a3e6addb54ec992477a7e4de1e565: FlushMRSOp(0429753b77704850a6698673a6669bfc) complete. Timing: real 0.031s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":86,"dirs.run_cpu_time_us":240,"dirs.run_wall_time_us":1446,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1539,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:56.513595  1121 maintenance_manager.cc:419] P ff6a3e6addb54ec992477a7e4de1e565: Scheduling LogGCOp(0429753b77704850a6698673a6669bfc): free 112239330 bytes of WAL
I20260812 06:18:56.513816  1024 log_reader.cc:385] T 0429753b77704850a6698673a6669bfc: removed 11 log segments from log reader
I20260812 06:18:56.513880  1024 log.cc:1079] T 0429753b77704850a6698673a6669bfc P ff6a3e6addb54ec992477a7e4de1e565: Deleting log segment in path: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515527602152-532-0/minicluster-data/ts-0-root/wals/0429753b77704850a6698673a6669bfc/wal-000000014 (ops 66-70)
I20260812 06:18:56.513958  1024 log.cc:1079] T 0429753b77704850a6698673a6669bfc P ff6a3e6addb54ec992477a7e4de1e565: Deleting log segment in path: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515527602152-532-0/minicluster-data/ts-0-root/wals/0429753b77704850a6698673a6669bfc/wal-000000015 (ops 71-75)
I20260812 06:18:56.514024  1024 log.cc:1079] T 0429753b77704850a6698673a6669bfc P ff6a3e6addb54ec992477a7e4de1e565: Deleting log segment in path: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515527602152-532-0/minicluster-data/ts-0-root/wals/0429753b77704850a6698673a6669bfc/wal-000000016 (ops 76-80)
I20260812 06:18:56.514098  1024 log.cc:1079] T 0429753b77704850a6698673a6669bfc P ff6a3e6addb54ec992477a7e4de1e565: Deleting log segment in path: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515527602152-532-0/minicluster-data/ts-0-root/wals/0429753b77704850a6698673a6669bfc/wal-000000017 (ops 81-85)
I20260812 06:18:56.514164  1024 log.cc:1079] T 0429753b77704850a6698673a6669bfc P ff6a3e6addb54ec992477a7e4de1e565: Deleting log segment in path: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515527602152-532-0/minicluster-data/ts-0-root/wals/0429753b77704850a6698673a6669bfc/wal-000000018 (ops 86-90)
I20260812 06:18:56.514253  1024 log.cc:1079] T 0429753b77704850a6698673a6669bfc P ff6a3e6addb54ec992477a7e4de1e565: Deleting log segment in path: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515527602152-532-0/minicluster-data/ts-0-root/wals/0429753b77704850a6698673a6669bfc/wal-000000019 (ops 91-95)
I20260812 06:18:56.514297  1024 log.cc:1079] T 0429753b77704850a6698673a6669bfc P ff6a3e6addb54ec992477a7e4de1e565: Deleting log segment in path: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515527602152-532-0/minicluster-data/ts-0-root/wals/0429753b77704850a6698673a6669bfc/wal-000000020 (ops 96-100)
I20260812 06:18:56.514340  1024 log.cc:1079] T 0429753b77704850a6698673a6669bfc P ff6a3e6addb54ec992477a7e4de1e565: Deleting log segment in path: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515527602152-532-0/minicluster-data/ts-0-root/wals/0429753b77704850a6698673a6669bfc/wal-000000021 (ops 101-104)
I20260812 06:18:56.514380  1024 log.cc:1079] T 0429753b77704850a6698673a6669bfc P ff6a3e6addb54ec992477a7e4de1e565: Deleting log segment in path: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515527602152-532-0/minicluster-data/ts-0-root/wals/0429753b77704850a6698673a6669bfc/wal-000000022 (ops 105-109)
I20260812 06:18:56.514420  1024 log.cc:1079] T 0429753b77704850a6698673a6669bfc P ff6a3e6addb54ec992477a7e4de1e565: Deleting log segment in path: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515527602152-532-0/minicluster-data/ts-0-root/wals/0429753b77704850a6698673a6669bfc/wal-000000023 (ops 110-114)
I20260812 06:18:56.514495  1024 log.cc:1079] T 0429753b77704850a6698673a6669bfc P ff6a3e6addb54ec992477a7e4de1e565: Deleting log segment in path: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515527602152-532-0/minicluster-data/ts-0-root/wals/0429753b77704850a6698673a6669bfc/wal-000000024 (ops 115-119)
I20260812 06:18:56.544674  1024 maintenance_manager.cc:643] P ff6a3e6addb54ec992477a7e4de1e565: LogGCOp(0429753b77704850a6698673a6669bfc) complete. Timing: real 0.031s	user 0.006s	sys 0.023s Metrics: {}
I20260812 06:18:56.545133  1121 maintenance_manager.cc:419] P ff6a3e6addb54ec992477a7e4de1e565: Scheduling UndoDeltaBlockGCOp(0429753b77704850a6698673a6669bfc): 447 bytes on disk
I20260812 06:18:56.545572  1024 maintenance_manager.cc:643] P ff6a3e6addb54ec992477a7e4de1e565: UndoDeltaBlockGCOp(0429753b77704850a6698673a6669bfc) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":71,"lbm_reads_lt_1ms":4}
I20260812 06:18:56.546133  1121 maintenance_manager.cc:419] P ff6a3e6addb54ec992477a7e4de1e565: Scheduling FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc): perf score=3.181125
I20260812 06:18:56.568425  1024 maintenance_manager.cc:643] P ff6a3e6addb54ec992477a7e4de1e565: FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc) complete. Timing: real 0.022s	user 0.010s	sys 0.007s Metrics: {"bytes_written":4512904,"delete_count":0,"lbm_write_time_us":7722,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:56.569022  1121 maintenance_manager.cc:419] P ff6a3e6addb54ec992477a7e4de1e565: Scheduling FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc): perf score=2.188937
I20260812 06:18:56.587100  1024 maintenance_manager.cc:643] P ff6a3e6addb54ec992477a7e4de1e565: FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc) complete. Timing: real 0.018s	user 0.009s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6678,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:56.587708  1121 maintenance_manager.cc:419] P ff6a3e6addb54ec992477a7e4de1e565: Scheduling MajorDeltaCompactionOp(0429753b77704850a6698673a6669bfc): perf score=1.000000
I20260812 06:18:56.899861  1024 maintenance_manager.cc:643] P ff6a3e6addb54ec992477a7e4de1e565: MajorDeltaCompactionOp(0429753b77704850a6698673a6669bfc) complete. Timing: real 0.312s	user 0.209s	sys 0.090s Metrics: {"cfile_cache_miss":934,"cfile_cache_miss_bytes":41184571,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":354,"lbm_read_time_us":30564,"lbm_reads_lt_1ms":974,"lbm_write_time_us":53666,"lbm_writes_lt_1ms":943,"peak_mem_usage":112822188,"reinsert_count":0,"thread_start_us":386,"threads_started":6,"update_count":4500}
I20260812 06:18:56.900699  1121 maintenance_manager.cc:419] P ff6a3e6addb54ec992477a7e4de1e565: Scheduling FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc): perf score=26.001437
I20260812 06:18:56.985745  1024 maintenance_manager.cc:643] P ff6a3e6addb54ec992477a7e4de1e565: FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc) complete. Timing: real 0.085s	user 0.049s	sys 0.025s Metrics: {"bytes_written":28717138,"delete_count":0,"lbm_write_time_us":36594,"lbm_writes_lt_1ms":703,"reinsert_count":0,"update_count":3500}
I20260812 06:18:56.986277  1121 maintenance_manager.cc:419] P ff6a3e6addb54ec992477a7e4de1e565: Scheduling FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc): perf score=2.188937
I20260812 06:18:56.997087  1024 maintenance_manager.cc:643] P ff6a3e6addb54ec992477a7e4de1e565: FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4329,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:56.997516  1121 maintenance_manager.cc:419] P ff6a3e6addb54ec992477a7e4de1e565: Scheduling MajorDeltaCompactionOp(0429753b77704850a6698673a6669bfc): perf score=1.000000
I20260812 06:18:57.274577  1024 maintenance_manager.cc:643] P ff6a3e6addb54ec992477a7e4de1e565: MajorDeltaCompactionOp(0429753b77704850a6698673a6669bfc) complete. Timing: real 0.277s	user 0.173s	sys 0.092s Metrics: {"cfile_cache_miss":832,"cfile_cache_miss_bytes":37081925,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":643,"lbm_read_time_us":21828,"lbm_reads_lt_1ms":872,"lbm_write_time_us":48338,"lbm_writes_lt_1ms":843,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":4096,"update_count":4000}
I20260812 06:18:57.275472  1121 maintenance_manager.cc:419] P ff6a3e6addb54ec992477a7e4de1e565: Scheduling FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc): perf score=22.032687
I20260812 06:18:57.351298  1024 maintenance_manager.cc:643] P ff6a3e6addb54ec992477a7e4de1e565: FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc) complete. Timing: real 0.076s	user 0.055s	sys 0.020s Metrics: {"bytes_written":24614722,"delete_count":0,"lbm_write_time_us":33453,"lbm_writes_lt_1ms":603,"reinsert_count":0,"update_count":3000}
I20260812 06:18:57.351886  1121 maintenance_manager.cc:419] P ff6a3e6addb54ec992477a7e4de1e565: Scheduling FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc): perf score=2.188937
I20260812 06:18:57.374449  1024 maintenance_manager.cc:643] P ff6a3e6addb54ec992477a7e4de1e565: FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc) complete. Timing: real 0.022s	user 0.003s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6433,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:57.374904  1121 maintenance_manager.cc:419] P ff6a3e6addb54ec992477a7e4de1e565: Scheduling FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc): perf score=2.188937
I20260812 06:18:57.386339  1024 maintenance_manager.cc:643] P ff6a3e6addb54ec992477a7e4de1e565: FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc) complete. Timing: real 0.011s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4551,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:57.386778  1121 maintenance_manager.cc:419] P ff6a3e6addb54ec992477a7e4de1e565: Scheduling MajorDeltaCompactionOp(0429753b77704850a6698673a6669bfc): perf score=1.000000
I20260812 06:18:57.594775  1024 maintenance_manager.cc:643] P ff6a3e6addb54ec992477a7e4de1e565: MajorDeltaCompactionOp(0429753b77704850a6698673a6669bfc) complete. Timing: real 0.208s	user 0.151s	sys 0.054s Metrics: {"cfile_cache_miss":833,"cfile_cache_miss_bytes":37082039,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":792,"lbm_read_time_us":15907,"lbm_reads_lt_1ms":873,"lbm_write_time_us":45610,"lbm_writes_lt_1ms":843,"mutex_wait_us":396,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":8448,"update_count":4000}
I20260812 06:18:57.595546  1121 maintenance_manager.cc:419] P ff6a3e6addb54ec992477a7e4de1e565: Scheduling FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc): perf score=18.063937
I20260812 06:18:57.659480  1024 maintenance_manager.cc:643] P ff6a3e6addb54ec992477a7e4de1e565: FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc) complete. Timing: real 0.064s	user 0.037s	sys 0.026s Metrics: {"bytes_written":20512319,"delete_count":0,"lbm_write_time_us":28345,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:57.660081  1121 maintenance_manager.cc:419] P ff6a3e6addb54ec992477a7e4de1e565: Scheduling FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc): perf score=2.188937
I20260812 06:18:57.678485  1024 maintenance_manager.cc:643] P ff6a3e6addb54ec992477a7e4de1e565: FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc) complete. Timing: real 0.018s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5867,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:57.679093  1121 maintenance_manager.cc:419] P ff6a3e6addb54ec992477a7e4de1e565: Scheduling MajorDeltaCompactionOp(0429753b77704850a6698673a6669bfc): perf score=1.000000
I20260812 06:18:57.853060  1024 maintenance_manager.cc:643] P ff6a3e6addb54ec992477a7e4de1e565: MajorDeltaCompactionOp(0429753b77704850a6698673a6669bfc) complete. Timing: real 0.173s	user 0.133s	sys 0.040s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877106,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":57,"lbm_read_time_us":12200,"lbm_reads_lt_1ms":664,"lbm_write_time_us":37501,"lbm_writes_lt_1ms":643,"mutex_wait_us":59,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":6784,"update_count":3000}
I20260812 06:18:57.853912  1121 maintenance_manager.cc:419] P ff6a3e6addb54ec992477a7e4de1e565: Scheduling FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc): perf score=14.095187
I20260812 06:18:57.901963  1024 maintenance_manager.cc:643] P ff6a3e6addb54ec992477a7e4de1e565: FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc) complete. Timing: real 0.048s	user 0.023s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20783,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:57.902524  1121 maintenance_manager.cc:419] P ff6a3e6addb54ec992477a7e4de1e565: Scheduling FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc): perf score=2.188937
I20260812 06:18:57.917647  1024 maintenance_manager.cc:643] P ff6a3e6addb54ec992477a7e4de1e565: FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5743,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:57.918211  1121 maintenance_manager.cc:419] P ff6a3e6addb54ec992477a7e4de1e565: Scheduling FlushMRSOp(0429753b77704850a6698673a6669bfc): perf score=1.000000
I20260812 06:18:57.947981  1024 maintenance_manager.cc:643] P ff6a3e6addb54ec992477a7e4de1e565: FlushMRSOp(0429753b77704850a6698673a6669bfc) complete. Timing: real 0.029s	user 0.022s	sys 0.005s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":74,"dirs.run_cpu_time_us":267,"dirs.run_wall_time_us":1271,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1604,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:57.948753  1121 maintenance_manager.cc:419] P ff6a3e6addb54ec992477a7e4de1e565: Scheduling LogGCOp(0429753b77704850a6698673a6669bfc): free 120100540 bytes of WAL
I20260812 06:18:57.949002  1024 log_reader.cc:385] T 0429753b77704850a6698673a6669bfc: removed 12 log segments from log reader
I20260812 06:18:57.949081  1024 log.cc:1079] T 0429753b77704850a6698673a6669bfc P ff6a3e6addb54ec992477a7e4de1e565: Deleting log segment in path: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515527602152-532-0/minicluster-data/ts-0-root/wals/0429753b77704850a6698673a6669bfc/wal-000000025 (ops 120-124)
I20260812 06:18:57.949138  1024 log.cc:1079] T 0429753b77704850a6698673a6669bfc P ff6a3e6addb54ec992477a7e4de1e565: Deleting log segment in path: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515527602152-532-0/minicluster-data/ts-0-root/wals/0429753b77704850a6698673a6669bfc/wal-000000026 (ops 125-128)
I20260812 06:18:57.949179  1024 log.cc:1079] T 0429753b77704850a6698673a6669bfc P ff6a3e6addb54ec992477a7e4de1e565: Deleting log segment in path: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515527602152-532-0/minicluster-data/ts-0-root/wals/0429753b77704850a6698673a6669bfc/wal-000000027 (ops 129-133)
I20260812 06:18:57.949225  1024 log.cc:1079] T 0429753b77704850a6698673a6669bfc P ff6a3e6addb54ec992477a7e4de1e565: Deleting log segment in path: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515527602152-532-0/minicluster-data/ts-0-root/wals/0429753b77704850a6698673a6669bfc/wal-000000028 (ops 134-138)
I20260812 06:18:57.949263  1024 log.cc:1079] T 0429753b77704850a6698673a6669bfc P ff6a3e6addb54ec992477a7e4de1e565: Deleting log segment in path: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515527602152-532-0/minicluster-data/ts-0-root/wals/0429753b77704850a6698673a6669bfc/wal-000000029 (ops 139-143)
I20260812 06:18:57.949301  1024 log.cc:1079] T 0429753b77704850a6698673a6669bfc P ff6a3e6addb54ec992477a7e4de1e565: Deleting log segment in path: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515527602152-532-0/minicluster-data/ts-0-root/wals/0429753b77704850a6698673a6669bfc/wal-000000030 (ops 144-148)
I20260812 06:18:57.949338  1024 log.cc:1079] T 0429753b77704850a6698673a6669bfc P ff6a3e6addb54ec992477a7e4de1e565: Deleting log segment in path: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515527602152-532-0/minicluster-data/ts-0-root/wals/0429753b77704850a6698673a6669bfc/wal-000000031 (ops 149-152)
I20260812 06:18:57.949378  1024 log.cc:1079] T 0429753b77704850a6698673a6669bfc P ff6a3e6addb54ec992477a7e4de1e565: Deleting log segment in path: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515527602152-532-0/minicluster-data/ts-0-root/wals/0429753b77704850a6698673a6669bfc/wal-000000032 (ops 153-157)
I20260812 06:18:57.949414  1024 log.cc:1079] T 0429753b77704850a6698673a6669bfc P ff6a3e6addb54ec992477a7e4de1e565: Deleting log segment in path: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515527602152-532-0/minicluster-data/ts-0-root/wals/0429753b77704850a6698673a6669bfc/wal-000000033 (ops 158-162)
I20260812 06:18:57.949451  1024 log.cc:1079] T 0429753b77704850a6698673a6669bfc P ff6a3e6addb54ec992477a7e4de1e565: Deleting log segment in path: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515527602152-532-0/minicluster-data/ts-0-root/wals/0429753b77704850a6698673a6669bfc/wal-000000034 (ops 163-167)
I20260812 06:18:57.949489  1024 log.cc:1079] T 0429753b77704850a6698673a6669bfc P ff6a3e6addb54ec992477a7e4de1e565: Deleting log segment in path: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515527602152-532-0/minicluster-data/ts-0-root/wals/0429753b77704850a6698673a6669bfc/wal-000000035 (ops 168-172)
I20260812 06:18:57.949535  1024 log.cc:1079] T 0429753b77704850a6698673a6669bfc P ff6a3e6addb54ec992477a7e4de1e565: Deleting log segment in path: /tmp/dist-test-taskyz0P90/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515527602152-532-0/minicluster-data/ts-0-root/wals/0429753b77704850a6698673a6669bfc/wal-000000036 (ops 173-176)
I20260812 06:18:57.979154  1024 maintenance_manager.cc:643] P ff6a3e6addb54ec992477a7e4de1e565: LogGCOp(0429753b77704850a6698673a6669bfc) complete. Timing: real 0.030s	user 0.002s	sys 0.027s Metrics: {}
I20260812 06:18:57.979638  1121 maintenance_manager.cc:419] P ff6a3e6addb54ec992477a7e4de1e565: Scheduling UndoDeltaBlockGCOp(0429753b77704850a6698673a6669bfc): 449 bytes on disk
I20260812 06:18:57.980096  1024 maintenance_manager.cc:643] P ff6a3e6addb54ec992477a7e4de1e565: UndoDeltaBlockGCOp(0429753b77704850a6698673a6669bfc) 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:18:57.980753  1121 maintenance_manager.cc:419] P ff6a3e6addb54ec992477a7e4de1e565: Scheduling FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc): perf score=3.181125
I20260812 06:18:57.996030  1024 maintenance_manager.cc:643] P ff6a3e6addb54ec992477a7e4de1e565: FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":5128263,"delete_count":0,"lbm_write_time_us":5963,"lbm_writes_lt_1ms":128,"reinsert_count":0,"update_count":625}
I20260812 06:18:57.996546  1121 maintenance_manager.cc:419] P ff6a3e6addb54ec992477a7e4de1e565: Scheduling FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc): perf score=1.196750
I20260812 06:18:58.009369  1024 maintenance_manager.cc:643] P ff6a3e6addb54ec992477a7e4de1e565: FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc) complete. Timing: real 0.013s	user 0.003s	sys 0.007s Metrics: {"bytes_written":3077030,"delete_count":0,"lbm_write_time_us":4693,"lbm_writes_lt_1ms":78,"reinsert_count":0,"update_count":375}
I20260812 06:18:58.010357  1121 maintenance_manager.cc:419] P ff6a3e6addb54ec992477a7e4de1e565: Scheduling MajorDeltaCompactionOp(0429753b77704850a6698673a6669bfc): perf score=1.000000
I20260812 06:18:58.202970  1024 maintenance_manager.cc:643] P ff6a3e6addb54ec992477a7e4de1e565: MajorDeltaCompactionOp(0429753b77704850a6698673a6669bfc) complete. Timing: real 0.192s	user 0.124s	sys 0.069s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979725,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":162,"lbm_read_time_us":16748,"lbm_reads_lt_1ms":774,"lbm_write_time_us":40298,"lbm_writes_lt_1ms":743,"mutex_wait_us":25,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":11520,"thread_start_us":104,"threads_started":1,"update_count":3500}
I20260812 06:18:58.206908  1121 maintenance_manager.cc:419] P ff6a3e6addb54ec992477a7e4de1e565: Scheduling FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc): perf score=15.087375
I20260812 06:18:58.262387  1024 maintenance_manager.cc:643] P ff6a3e6addb54ec992477a7e4de1e565: FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc) complete. Timing: real 0.055s	user 0.034s	sys 0.020s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":24641,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:18:58.262861  1121 maintenance_manager.cc:419] P ff6a3e6addb54ec992477a7e4de1e565: Scheduling FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc): perf score=2.188937
I20260812 06:18:58.287948  1024 maintenance_manager.cc:643] P ff6a3e6addb54ec992477a7e4de1e565: FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc) complete. Timing: real 0.025s	user 0.006s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4023,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:58.288429  1121 maintenance_manager.cc:419] P ff6a3e6addb54ec992477a7e4de1e565: Scheduling FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc): perf score=2.188937
I20260812 06:18:58.303570  1024 maintenance_manager.cc:643] P ff6a3e6addb54ec992477a7e4de1e565: FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc) complete. Timing: real 0.015s	user 0.009s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6007,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:58.304234  1121 maintenance_manager.cc:419] P ff6a3e6addb54ec992477a7e4de1e565: Scheduling MajorDeltaCompactionOp(0429753b77704850a6698673a6669bfc): perf score=1.000000
I20260812 06:18:58.478941   532 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.805s	user 1.826s	sys 0.115s
I20260812 06:18:58.482055  1024 maintenance_manager.cc:643] P ff6a3e6addb54ec992477a7e4de1e565: MajorDeltaCompactionOp(0429753b77704850a6698673a6669bfc) complete. Timing: real 0.178s	user 0.145s	sys 0.030s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877205,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":809,"lbm_read_time_us":14187,"lbm_reads_lt_1ms":673,"lbm_write_time_us":34972,"lbm_writes_lt_1ms":643,"mutex_wait_us":46,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":7296,"update_count":3000}
I20260812 06:18:58.482707  1121 maintenance_manager.cc:419] P ff6a3e6addb54ec992477a7e4de1e565: Scheduling FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc): perf score=14.095187
I20260812 06:18:58.508926   532 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.030s	user 0.001s	sys 0.000s
I20260812 06:18:58.509443   532 tablet_server.cc:179] TabletServer@127.0.133.1:0 shutting down...
I20260812 06:18:58.546214  1024 maintenance_manager.cc:643] P ff6a3e6addb54ec992477a7e4de1e565: FlushDeltaMemStoresOp(0429753b77704850a6698673a6669bfc) complete. Timing: real 0.063s	user 0.041s	sys 0.019s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":30303,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:18:58.546923   532 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:58.547158   532 tablet_replica.cc:333] T 0429753b77704850a6698673a6669bfc P ff6a3e6addb54ec992477a7e4de1e565: stopping tablet replica
I20260812 06:18:58.547317   532 raft_consensus.cc:2243] T 0429753b77704850a6698673a6669bfc P ff6a3e6addb54ec992477a7e4de1e565 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:58.547453   532 raft_consensus.cc:2272] T 0429753b77704850a6698673a6669bfc P ff6a3e6addb54ec992477a7e4de1e565 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:58.551543   532 tablet_server.cc:196] TabletServer@127.0.133.1:0 shutdown complete.
I20260812 06:18:58.554292   532 master.cc:562] Master@127.0.133.62:37075 shutting down...
I20260812 06:18:58.558463   532 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 04b4ef270c5145a09b4514e41578668c [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:58.558588   532 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 04b4ef270c5145a09b4514e41578668c [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:58.558634   532 tablet_replica.cc:333] T 00000000000000000000000000000000 P 04b4ef270c5145a09b4514e41578668c: stopping tablet replica
I20260812 06:18:58.570896   532 master.cc:584] Master@127.0.133.62:37075 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5238 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11059 ms total)

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