[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:17:53.655946 28026 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.27.94.190:38981
I20260812 06:17:53.657112 28026 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:17:53.657887 28026 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:53.665400 28034 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:53.665452 28037 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:53.665856 28035 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:53.665940 28026 server_base.cc:1061] running on GCE node
I20260812 06:17:53.666733 28026 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:53.666852 28026 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:53.666887 28026 hybrid_clock.cc:648] HybridClock initialized: now 1786515473666885 us; error 0 us; skew 500 ppm
I20260812 06:17:53.669060 28026 webserver.cc:533] Webserver started at http://127.27.94.190:45927/ using document root <none> and password file <none>
I20260812 06:17:53.669726 28026 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:53.669806 28026 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:53.670025 28026 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:53.671803 28026 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473644184-28026-0/minicluster-data/master-0-root/instance:
uuid: "ee1822d54d7b447bb119b6f18c4f45ee"
format_stamp: "Formatted at 2026-08-12 06:17:53 on dist-test-slave-9zdj"
I20260812 06:17:53.676251 28026 fs_manager.cc:696] Time spent creating directory manager: real 0.004s	user 0.005s	sys 0.000s
I20260812 06:17:53.678848 28042 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:53.680203 28026 fs_manager.cc:730] Time spent opening block manager: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:17:53.680333 28026 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473644184-28026-0/minicluster-data/master-0-root
uuid: "ee1822d54d7b447bb119b6f18c4f45ee"
format_stamp: "Formatted at 2026-08-12 06:17:53 on dist-test-slave-9zdj"
I20260812 06:17:53.680491 28026 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473644184-28026-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473644184-28026-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473644184-28026-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:53.695057 28026 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:53.695922 28026 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:17:53.696125 28026 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:53.706171 28026 rpc_server.cc:307] RPC server started. Bound to: 127.27.94.190:38981
I20260812 06:17:53.706172 28104 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.27.94.190:38981 every 8 connection(s)
I20260812 06:17:53.708889 28105 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:53.715144 28105 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P ee1822d54d7b447bb119b6f18c4f45ee: Bootstrap starting.
I20260812 06:17:53.717944 28105 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P ee1822d54d7b447bb119b6f18c4f45ee: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:53.719022 28105 log.cc:826] T 00000000000000000000000000000000 P ee1822d54d7b447bb119b6f18c4f45ee: Log is configured to *not* fsync() on all Append() calls
I20260812 06:17:53.721153 28105 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P ee1822d54d7b447bb119b6f18c4f45ee: No bootstrap required, opened a new log
I20260812 06:17:53.724248 28105 raft_consensus.cc:359] T 00000000000000000000000000000000 P ee1822d54d7b447bb119b6f18c4f45ee [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ee1822d54d7b447bb119b6f18c4f45ee" member_type: VOTER }
I20260812 06:17:53.724442 28105 raft_consensus.cc:385] T 00000000000000000000000000000000 P ee1822d54d7b447bb119b6f18c4f45ee [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:53.724517 28105 raft_consensus.cc:740] T 00000000000000000000000000000000 P ee1822d54d7b447bb119b6f18c4f45ee [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: ee1822d54d7b447bb119b6f18c4f45ee, State: Initialized, Role: FOLLOWER
I20260812 06:17:53.725283 28105 consensus_queue.cc:260] T 00000000000000000000000000000000 P ee1822d54d7b447bb119b6f18c4f45ee [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: "ee1822d54d7b447bb119b6f18c4f45ee" member_type: VOTER }
I20260812 06:17:53.725487 28105 raft_consensus.cc:399] T 00000000000000000000000000000000 P ee1822d54d7b447bb119b6f18c4f45ee [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:53.725565 28105 raft_consensus.cc:493] T 00000000000000000000000000000000 P ee1822d54d7b447bb119b6f18c4f45ee [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:53.725742 28105 raft_consensus.cc:3060] T 00000000000000000000000000000000 P ee1822d54d7b447bb119b6f18c4f45ee [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:53.726650 28105 raft_consensus.cc:515] T 00000000000000000000000000000000 P ee1822d54d7b447bb119b6f18c4f45ee [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ee1822d54d7b447bb119b6f18c4f45ee" member_type: VOTER }
I20260812 06:17:53.727149 28105 leader_election.cc:304] T 00000000000000000000000000000000 P ee1822d54d7b447bb119b6f18c4f45ee [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: ee1822d54d7b447bb119b6f18c4f45ee; no voters: 
I20260812 06:17:53.727578 28105 leader_election.cc:290] T 00000000000000000000000000000000 P ee1822d54d7b447bb119b6f18c4f45ee [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:53.727715 28110 raft_consensus.cc:2804] T 00000000000000000000000000000000 P ee1822d54d7b447bb119b6f18c4f45ee [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:53.728016 28110 raft_consensus.cc:697] T 00000000000000000000000000000000 P ee1822d54d7b447bb119b6f18c4f45ee [term 1 LEADER]: Becoming Leader. State: Replica: ee1822d54d7b447bb119b6f18c4f45ee, State: Running, Role: LEADER
I20260812 06:17:53.728543 28110 consensus_queue.cc:237] T 00000000000000000000000000000000 P ee1822d54d7b447bb119b6f18c4f45ee [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: "ee1822d54d7b447bb119b6f18c4f45ee" member_type: VOTER }
I20260812 06:17:53.728718 28105 sys_catalog.cc:565] T 00000000000000000000000000000000 P ee1822d54d7b447bb119b6f18c4f45ee [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:53.730559 28112 sys_catalog.cc:455] T 00000000000000000000000000000000 P ee1822d54d7b447bb119b6f18c4f45ee [sys.catalog]: SysCatalogTable state changed. Reason: New leader ee1822d54d7b447bb119b6f18c4f45ee. Latest consensus state: current_term: 1 leader_uuid: "ee1822d54d7b447bb119b6f18c4f45ee" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ee1822d54d7b447bb119b6f18c4f45ee" member_type: VOTER } }
I20260812 06:17:53.730607 28111 sys_catalog.cc:455] T 00000000000000000000000000000000 P ee1822d54d7b447bb119b6f18c4f45ee [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "ee1822d54d7b447bb119b6f18c4f45ee" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ee1822d54d7b447bb119b6f18c4f45ee" member_type: VOTER } }
I20260812 06:17:53.730697 28112 sys_catalog.cc:458] T 00000000000000000000000000000000 P ee1822d54d7b447bb119b6f18c4f45ee [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:53.730726 28111 sys_catalog.cc:458] T 00000000000000000000000000000000 P ee1822d54d7b447bb119b6f18c4f45ee [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:53.731127 28123 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:53.731387 28026 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:53.734117 28123 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:53.739781 28123 catalog_manager.cc:1383] Generated new cluster ID: e3913d8d55974a75bf66b18f4dab6cf3
I20260812 06:17:53.739992 28123 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:53.750981 28123 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:53.752005 28123 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:53.765830 28123 catalog_manager.cc:6092] T 00000000000000000000000000000000 P ee1822d54d7b447bb119b6f18c4f45ee: Generated new TSK 0
I20260812 06:17:53.766637 28123 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:53.797122 28026 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:53.800518 28131 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:53.800595 28132 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:53.800956 28134 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:53.801318 28026 server_base.cc:1061] running on GCE node
I20260812 06:17:53.801509 28026 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:53.801559 28026 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:53.801582 28026 hybrid_clock.cc:648] HybridClock initialized: now 1786515473801583 us; error 0 us; skew 500 ppm
I20260812 06:17:53.802721 28026 webserver.cc:533] Webserver started at http://127.27.94.129:46793/ using document root <none> and password file <none>
I20260812 06:17:53.802917 28026 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:53.802980 28026 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:53.803061 28026 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:53.803557 28026 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473644184-28026-0/minicluster-data/ts-0-root/instance:
uuid: "92ede8811f3b4136aaa60b7dc86dbd46"
format_stamp: "Formatted at 2026-08-12 06:17:53 on dist-test-slave-9zdj"
I20260812 06:17:53.805608 28026 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:17:53.806970 28139 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:53.807319 28026 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:53.807446 28026 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473644184-28026-0/minicluster-data/ts-0-root
uuid: "92ede8811f3b4136aaa60b7dc86dbd46"
format_stamp: "Formatted at 2026-08-12 06:17:53 on dist-test-slave-9zdj"
I20260812 06:17:53.807560 28026 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473644184-28026-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473644184-28026-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473644184-28026-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:53.827171 28026 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:53.827915 28026 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:53.828629 28026 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:53.829995 28026 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:53.830158 28026 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:53.830302 28026 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:53.830379 28026 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:53.840737 28026 rpc_server.cc:307] RPC server started. Bound to: 127.27.94.129:38027
I20260812 06:17:53.840798 28217 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.27.94.129:38027 every 8 connection(s)
I20260812 06:17:53.864966 28218 heartbeater.cc:344] Connected to a master server at 127.27.94.190:38981
I20260812 06:17:53.865303 28218 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:53.865967 28218 heartbeater.cc:507] Master 127.27.94.190:38981 requested a full tablet report, sending...
I20260812 06:17:53.867820 28061 ts_manager.cc:194] Registered new tserver with Master: 92ede8811f3b4136aaa60b7dc86dbd46 (127.27.94.129:38027)
I20260812 06:17:53.868593 28026 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.02712087s
I20260812 06:17:53.869647 28061 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:60758
I20260812 06:17:53.880633 28061 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:60770:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:17:53.897110 28175 tablet_service.cc:1511] Processing CreateTablet for tablet 27388575d3284ebeb8c96e0a1c1a6c53 (DEFAULT_TABLE table=heavy-update-compaction-test [id=202bfa48adec4e279fe2a4ce5bdc00dd]), partition=
I20260812 06:17:53.897765 28175 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 27388575d3284ebeb8c96e0a1c1a6c53. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:53.900091 28230 tablet_bootstrap.cc:492] T 27388575d3284ebeb8c96e0a1c1a6c53 P 92ede8811f3b4136aaa60b7dc86dbd46: Bootstrap starting.
I20260812 06:17:53.901489 28230 tablet_bootstrap.cc:654] T 27388575d3284ebeb8c96e0a1c1a6c53 P 92ede8811f3b4136aaa60b7dc86dbd46: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:53.902946 28230 tablet_bootstrap.cc:492] T 27388575d3284ebeb8c96e0a1c1a6c53 P 92ede8811f3b4136aaa60b7dc86dbd46: No bootstrap required, opened a new log
I20260812 06:17:53.903095 28230 ts_tablet_manager.cc:1403] T 27388575d3284ebeb8c96e0a1c1a6c53 P 92ede8811f3b4136aaa60b7dc86dbd46: Time spent bootstrapping tablet: real 0.003s	user 0.000s	sys 0.002s
I20260812 06:17:53.903609 28230 raft_consensus.cc:359] T 27388575d3284ebeb8c96e0a1c1a6c53 P 92ede8811f3b4136aaa60b7dc86dbd46 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "92ede8811f3b4136aaa60b7dc86dbd46" member_type: VOTER last_known_addr { host: "127.27.94.129" port: 38027 } }
I20260812 06:17:53.903743 28230 raft_consensus.cc:385] T 27388575d3284ebeb8c96e0a1c1a6c53 P 92ede8811f3b4136aaa60b7dc86dbd46 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:53.903808 28230 raft_consensus.cc:740] T 27388575d3284ebeb8c96e0a1c1a6c53 P 92ede8811f3b4136aaa60b7dc86dbd46 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 92ede8811f3b4136aaa60b7dc86dbd46, State: Initialized, Role: FOLLOWER
I20260812 06:17:53.903972 28230 consensus_queue.cc:260] T 27388575d3284ebeb8c96e0a1c1a6c53 P 92ede8811f3b4136aaa60b7dc86dbd46 [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: "92ede8811f3b4136aaa60b7dc86dbd46" member_type: VOTER last_known_addr { host: "127.27.94.129" port: 38027 } }
I20260812 06:17:53.904068 28230 raft_consensus.cc:399] T 27388575d3284ebeb8c96e0a1c1a6c53 P 92ede8811f3b4136aaa60b7dc86dbd46 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:53.904126 28230 raft_consensus.cc:493] T 27388575d3284ebeb8c96e0a1c1a6c53 P 92ede8811f3b4136aaa60b7dc86dbd46 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:53.904187 28230 raft_consensus.cc:3060] T 27388575d3284ebeb8c96e0a1c1a6c53 P 92ede8811f3b4136aaa60b7dc86dbd46 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:53.905042 28230 raft_consensus.cc:515] T 27388575d3284ebeb8c96e0a1c1a6c53 P 92ede8811f3b4136aaa60b7dc86dbd46 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "92ede8811f3b4136aaa60b7dc86dbd46" member_type: VOTER last_known_addr { host: "127.27.94.129" port: 38027 } }
I20260812 06:17:53.905232 28230 leader_election.cc:304] T 27388575d3284ebeb8c96e0a1c1a6c53 P 92ede8811f3b4136aaa60b7dc86dbd46 [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: 92ede8811f3b4136aaa60b7dc86dbd46; no voters: 
I20260812 06:17:53.905501 28230 leader_election.cc:290] T 27388575d3284ebeb8c96e0a1c1a6c53 P 92ede8811f3b4136aaa60b7dc86dbd46 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:53.905661 28232 raft_consensus.cc:2804] T 27388575d3284ebeb8c96e0a1c1a6c53 P 92ede8811f3b4136aaa60b7dc86dbd46 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:53.905984 28232 raft_consensus.cc:697] T 27388575d3284ebeb8c96e0a1c1a6c53 P 92ede8811f3b4136aaa60b7dc86dbd46 [term 1 LEADER]: Becoming Leader. State: Replica: 92ede8811f3b4136aaa60b7dc86dbd46, State: Running, Role: LEADER
I20260812 06:17:53.906031 28230 ts_tablet_manager.cc:1434] T 27388575d3284ebeb8c96e0a1c1a6c53 P 92ede8811f3b4136aaa60b7dc86dbd46: Time spent starting tablet: real 0.003s	user 0.000s	sys 0.003s
I20260812 06:17:53.906208 28232 consensus_queue.cc:237] T 27388575d3284ebeb8c96e0a1c1a6c53 P 92ede8811f3b4136aaa60b7dc86dbd46 [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: "92ede8811f3b4136aaa60b7dc86dbd46" member_type: VOTER last_known_addr { host: "127.27.94.129" port: 38027 } }
I20260812 06:17:53.906602 28218 heartbeater.cc:499] Master 127.27.94.190:38981 was elected leader, sending a full tablet report...
I20260812 06:17:53.909323 28061 catalog_manager.cc:5719] T 27388575d3284ebeb8c96e0a1c1a6c53 P 92ede8811f3b4136aaa60b7dc86dbd46 reported cstate change: term changed from 0 to 1, leader changed from <none> to 92ede8811f3b4136aaa60b7dc86dbd46 (127.27.94.129). New cstate: current_term: 1 leader_uuid: "92ede8811f3b4136aaa60b7dc86dbd46" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "92ede8811f3b4136aaa60b7dc86dbd46" member_type: VOTER last_known_addr { host: "127.27.94.129" port: 38027 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:53.989744 28026 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.070s	user 0.018s	sys 0.016s
I20260812 06:17:54.092052 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling FlushMRSOp(27388575d3284ebeb8c96e0a1c1a6c53): perf score=11.117440
I20260812 06:17:54.229290 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: FlushMRSOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.137s	user 0.105s	sys 0.028s Metrics: {"bytes_written":11897251,"cfile_init":1,"compiler_manager_pool.queue_time_us":222,"delete_count":0,"dirs.queue_time_us":80,"dirs.run_cpu_time_us":203,"dirs.run_wall_time_us":946,"drs_written":1,"lbm_read_time_us":97,"lbm_reads_lt_1ms":4,"lbm_write_time_us":32282,"lbm_writes_lt_1ms":557,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"thread_start_us":150,"threads_started":1,"update_count":1450}
I20260812 06:17:54.230723 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling MajorDeltaCompactionOp(27388575d3284ebeb8c96e0a1c1a6c53): perf score=1.000000
I20260812 06:17:54.364092 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: MajorDeltaCompactionOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.133s	user 0.087s	sys 0.035s Metrics: {"cfile_cache_miss":321,"cfile_cache_miss_bytes":16118542,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":535,"lbm_read_time_us":7611,"lbm_reads_lt_1ms":353,"lbm_write_time_us":22515,"lbm_writes_lt_1ms":333,"peak_mem_usage":36812022,"reinsert_count":0,"thread_start_us":338,"threads_started":5,"update_count":1450}
I20260812 06:17:54.364611 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling LogGCOp(27388575d3284ebeb8c96e0a1c1a6c53): free 8725963 bytes of WAL
I20260812 06:17:54.364908 28144 log_reader.cc:385] T 27388575d3284ebeb8c96e0a1c1a6c53: removed 1 log segments from log reader
I20260812 06:17:54.364986 28144 log.cc:1079] T 27388575d3284ebeb8c96e0a1c1a6c53 P 92ede8811f3b4136aaa60b7dc86dbd46: Deleting log segment in path: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473644184-28026-0/minicluster-data/ts-0-root/wals/27388575d3284ebeb8c96e0a1c1a6c53/wal-000000001 (ops 1-6)
I20260812 06:17:54.367081 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: LogGCOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.002s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:17:54.367475 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling UndoDeltaBlockGCOp(27388575d3284ebeb8c96e0a1c1a6c53): 8616791 bytes on disk
I20260812 06:17:54.368017 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: UndoDeltaBlockGCOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":72,"lbm_reads_lt_1ms":4}
I20260812 06:17:54.368454 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53): perf score=10.126437
I20260812 06:17:54.419356 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.051s	user 0.028s	sys 0.008s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16521,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:54.419950 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53): perf score=2.188937
I20260812 06:17:54.436007 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.016s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5878,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:54.436718 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling MajorDeltaCompactionOp(27388575d3284ebeb8c96e0a1c1a6c53): perf score=1.000000
I20260812 06:17:54.567967 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: MajorDeltaCompactionOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.131s	user 0.099s	sys 0.032s 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":662,"lbm_read_time_us":9840,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24103,"lbm_writes_lt_1ms":443,"mutex_wait_us":25,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":87552,"update_count":2000}
I20260812 06:17:54.568635 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53): perf score=10.126437
I20260812 06:17:54.623189 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.054s	user 0.023s	sys 0.019s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15214,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:54.623844 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53): perf score=2.188937
I20260812 06:17:54.635525 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4424,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:54.636039 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling MajorDeltaCompactionOp(27388575d3284ebeb8c96e0a1c1a6c53): perf score=1.000000
I20260812 06:17:54.792706 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: MajorDeltaCompactionOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.156s	user 0.107s	sys 0.049s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631310,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":372,"lbm_read_time_us":12440,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24565,"lbm_writes_lt_1ms":443,"mutex_wait_us":73,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2000}
I20260812 06:17:54.793479 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53): perf score=10.126437
I20260812 06:17:54.844295 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.051s	user 0.026s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15390,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:54.844945 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53): perf score=2.188937
I20260812 06:17:54.860313 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6188,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:54.860832 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling MajorDeltaCompactionOp(27388575d3284ebeb8c96e0a1c1a6c53): perf score=1.000000
I20260812 06:17:55.001065 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: MajorDeltaCompactionOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.140s	user 0.116s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1497,"lbm_read_time_us":10210,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27406,"lbm_writes_lt_1ms":443,"mutex_wait_us":550,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9984,"update_count":2000}
I20260812 06:17:55.001890 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53): perf score=10.126437
I20260812 06:17:55.045321 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.043s	user 0.030s	sys 0.009s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18546,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:55.045853 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53): perf score=2.188937
I20260812 06:17:55.061144 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5742,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:55.061730 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling MajorDeltaCompactionOp(27388575d3284ebeb8c96e0a1c1a6c53): perf score=1.000000
I20260812 06:17:55.188120 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: MajorDeltaCompactionOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.126s	user 0.105s	sys 0.021s 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":434,"lbm_read_time_us":9834,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25020,"lbm_writes_lt_1ms":443,"mutex_wait_us":47,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:17:55.188668 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53): perf score=10.126437
I20260812 06:17:55.238157 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.049s	user 0.019s	sys 0.027s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15994,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:55.238940 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53): perf score=2.188937
I20260812 06:17:55.250403 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4455,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:55.250932 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling MajorDeltaCompactionOp(27388575d3284ebeb8c96e0a1c1a6c53): perf score=1.000000
I20260812 06:17:55.401407 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: MajorDeltaCompactionOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.150s	user 0.114s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1392,"lbm_read_time_us":11826,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24202,"lbm_writes_lt_1ms":443,"mutex_wait_us":308,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:55.402119 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53): perf score=10.126437
I20260812 06:17:55.444365 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.042s	user 0.022s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15349,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:55.444955 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53): perf score=2.188937
I20260812 06:17:55.456794 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4247,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:55.457747 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling MajorDeltaCompactionOp(27388575d3284ebeb8c96e0a1c1a6c53): perf score=1.000000
I20260812 06:17:55.593899 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: MajorDeltaCompactionOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.136s	user 0.115s	sys 0.021s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1927,"lbm_read_time_us":9499,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26976,"lbm_writes_lt_1ms":443,"mutex_wait_us":651,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:55.594640 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53): perf score=10.126437
I20260812 06:17:55.627918 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.033s	user 0.018s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14287,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:55.628623 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53): perf score=2.188937
I20260812 06:17:55.641417 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4441,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:55.642022 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling FlushMRSOp(27388575d3284ebeb8c96e0a1c1a6c53): perf score=1.000000
I20260812 06:17:55.676254 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: FlushMRSOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.034s	user 0.029s	sys 0.004s Metrics: {"bytes_written":1234474,"cfile_init":1,"dirs.queue_time_us":68,"dirs.run_cpu_time_us":274,"dirs.run_wall_time_us":1842,"drs_written":1,"lbm_read_time_us":96,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1823,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:17:55.677107 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling LogGCOp(27388575d3284ebeb8c96e0a1c1a6c53): free 124257182 bytes of WAL
I20260812 06:17:55.677378 28144 log_reader.cc:385] T 27388575d3284ebeb8c96e0a1c1a6c53: removed 12 log segments from log reader
I20260812 06:17:55.677448 28144 log.cc:1079] T 27388575d3284ebeb8c96e0a1c1a6c53 P 92ede8811f3b4136aaa60b7dc86dbd46: Deleting log segment in path: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473644184-28026-0/minicluster-data/ts-0-root/wals/27388575d3284ebeb8c96e0a1c1a6c53/wal-000000002 (ops 7-11)
I20260812 06:17:55.677506 28144 log.cc:1079] T 27388575d3284ebeb8c96e0a1c1a6c53 P 92ede8811f3b4136aaa60b7dc86dbd46: Deleting log segment in path: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473644184-28026-0/minicluster-data/ts-0-root/wals/27388575d3284ebeb8c96e0a1c1a6c53/wal-000000003 (ops 12-16)
I20260812 06:17:55.677569 28144 log.cc:1079] T 27388575d3284ebeb8c96e0a1c1a6c53 P 92ede8811f3b4136aaa60b7dc86dbd46: Deleting log segment in path: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473644184-28026-0/minicluster-data/ts-0-root/wals/27388575d3284ebeb8c96e0a1c1a6c53/wal-000000004 (ops 17-20)
I20260812 06:17:55.677632 28144 log.cc:1079] T 27388575d3284ebeb8c96e0a1c1a6c53 P 92ede8811f3b4136aaa60b7dc86dbd46: Deleting log segment in path: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473644184-28026-0/minicluster-data/ts-0-root/wals/27388575d3284ebeb8c96e0a1c1a6c53/wal-000000005 (ops 21-25)
I20260812 06:17:55.677673 28144 log.cc:1079] T 27388575d3284ebeb8c96e0a1c1a6c53 P 92ede8811f3b4136aaa60b7dc86dbd46: Deleting log segment in path: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473644184-28026-0/minicluster-data/ts-0-root/wals/27388575d3284ebeb8c96e0a1c1a6c53/wal-000000006 (ops 26-30)
I20260812 06:17:55.677713 28144 log.cc:1079] T 27388575d3284ebeb8c96e0a1c1a6c53 P 92ede8811f3b4136aaa60b7dc86dbd46: Deleting log segment in path: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473644184-28026-0/minicluster-data/ts-0-root/wals/27388575d3284ebeb8c96e0a1c1a6c53/wal-000000007 (ops 31-35)
I20260812 06:17:55.677758 28144 log.cc:1079] T 27388575d3284ebeb8c96e0a1c1a6c53 P 92ede8811f3b4136aaa60b7dc86dbd46: Deleting log segment in path: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473644184-28026-0/minicluster-data/ts-0-root/wals/27388575d3284ebeb8c96e0a1c1a6c53/wal-000000008 (ops 36-40)
I20260812 06:17:55.677793 28144 log.cc:1079] T 27388575d3284ebeb8c96e0a1c1a6c53 P 92ede8811f3b4136aaa60b7dc86dbd46: Deleting log segment in path: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473644184-28026-0/minicluster-data/ts-0-root/wals/27388575d3284ebeb8c96e0a1c1a6c53/wal-000000009 (ops 41-45)
I20260812 06:17:55.677827 28144 log.cc:1079] T 27388575d3284ebeb8c96e0a1c1a6c53 P 92ede8811f3b4136aaa60b7dc86dbd46: Deleting log segment in path: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473644184-28026-0/minicluster-data/ts-0-root/wals/27388575d3284ebeb8c96e0a1c1a6c53/wal-000000010 (ops 46-50)
I20260812 06:17:55.677865 28144 log.cc:1079] T 27388575d3284ebeb8c96e0a1c1a6c53 P 92ede8811f3b4136aaa60b7dc86dbd46: Deleting log segment in path: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473644184-28026-0/minicluster-data/ts-0-root/wals/27388575d3284ebeb8c96e0a1c1a6c53/wal-000000011 (ops 51-55)
I20260812 06:17:55.677901 28144 log.cc:1079] T 27388575d3284ebeb8c96e0a1c1a6c53 P 92ede8811f3b4136aaa60b7dc86dbd46: Deleting log segment in path: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473644184-28026-0/minicluster-data/ts-0-root/wals/27388575d3284ebeb8c96e0a1c1a6c53/wal-000000012 (ops 56-60)
I20260812 06:17:55.677938 28144 log.cc:1079] T 27388575d3284ebeb8c96e0a1c1a6c53 P 92ede8811f3b4136aaa60b7dc86dbd46: Deleting log segment in path: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473644184-28026-0/minicluster-data/ts-0-root/wals/27388575d3284ebeb8c96e0a1c1a6c53/wal-000000013 (ops 61-65)
I20260812 06:17:55.708051 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: LogGCOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.031s	user 0.001s	sys 0.027s Metrics: {}
I20260812 06:17:55.708638 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53): perf score=3.181125
I20260812 06:17:55.727514 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.019s	user 0.008s	sys 0.008s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":7382,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:55.727999 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling LogGCOp(27388575d3284ebeb8c96e0a1c1a6c53): free 12017983 bytes of WAL
I20260812 06:17:55.728223 28144 log_reader.cc:385] T 27388575d3284ebeb8c96e0a1c1a6c53: removed 1 log segments from log reader
I20260812 06:17:55.728268 28144 log.cc:1079] T 27388575d3284ebeb8c96e0a1c1a6c53 P 92ede8811f3b4136aaa60b7dc86dbd46: Deleting log segment in path: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473644184-28026-0/minicluster-data/ts-0-root/wals/27388575d3284ebeb8c96e0a1c1a6c53/wal-000000014 (ops 66-70)
I20260812 06:17:55.730885 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: LogGCOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.003s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:17:55.731366 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53): perf score=2.188937
I20260812 06:17:55.743292 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.012s	user 0.002s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3852,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:55.744656 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling MajorDeltaCompactionOp(27388575d3284ebeb8c96e0a1c1a6c53): perf score=1.000000
I20260812 06:17:55.922016 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: MajorDeltaCompactionOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.177s	user 0.133s	sys 0.036s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836364,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":533,"lbm_read_time_us":11339,"lbm_reads_lt_1ms":674,"lbm_write_time_us":35511,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3200,"thread_start_us":89,"threads_started":1,"update_count":3000}
I20260812 06:17:55.922655 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling UndoDeltaBlockGCOp(27388575d3284ebeb8c96e0a1c1a6c53): 472 bytes on disk
I20260812 06:17:55.923296 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: UndoDeltaBlockGCOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":102,"lbm_reads_lt_1ms":4}
I20260812 06:17:55.924075 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53): perf score=14.095187
I20260812 06:17:55.976125 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.052s	user 0.029s	sys 0.020s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":23165,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:55.976797 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53): perf score=2.188937
I20260812 06:17:55.990530 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.014s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4938,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:55.991106 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling MajorDeltaCompactionOp(27388575d3284ebeb8c96e0a1c1a6c53): perf score=1.000000
I20260812 06:17:56.139654 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: MajorDeltaCompactionOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.148s	user 0.111s	sys 0.034s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733721,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":250,"lbm_read_time_us":11987,"lbm_reads_lt_1ms":564,"lbm_write_time_us":29891,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":27008,"update_count":2500}
I20260812 06:17:56.140239 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53): perf score=10.126437
I20260812 06:17:56.188030 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.048s	user 0.029s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18809,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:56.188743 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53): perf score=2.188937
I20260812 06:17:56.204617 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.016s	user 0.002s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6316,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:56.205186 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling MajorDeltaCompactionOp(27388575d3284ebeb8c96e0a1c1a6c53): perf score=1.000000
I20260812 06:17:56.360042 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: MajorDeltaCompactionOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.155s	user 0.128s	sys 0.026s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1367,"lbm_read_time_us":10013,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29659,"lbm_writes_lt_1ms":443,"mutex_wait_us":398,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:56.360729 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53): perf score=10.126437
I20260812 06:17:56.412297 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.051s	user 0.020s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17117,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:56.413035 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53): perf score=2.188937
I20260812 06:17:56.425736 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.012s	user 0.009s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4772,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:56.426453 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling MajorDeltaCompactionOp(27388575d3284ebeb8c96e0a1c1a6c53): perf score=1.000000
I20260812 06:17:56.561976 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: MajorDeltaCompactionOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.135s	user 0.110s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":651,"lbm_read_time_us":10113,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25462,"lbm_writes_lt_1ms":443,"mutex_wait_us":318,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:56.566252 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53): perf score=11.118625
I20260812 06:17:56.620241 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.054s	user 0.023s	sys 0.028s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":20216,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:17:56.620885 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53): perf score=2.188937
I20260812 06:17:56.640786 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.020s	user 0.003s	sys 0.012s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6532,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:56.641337 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling MajorDeltaCompactionOp(27388575d3284ebeb8c96e0a1c1a6c53): perf score=1.000000
I20260812 06:17:56.794251 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: MajorDeltaCompactionOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.153s	user 0.124s	sys 0.027s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631303,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":198,"lbm_read_time_us":10519,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24958,"lbm_writes_lt_1ms":443,"mutex_wait_us":30,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11392,"update_count":2000}
I20260812 06:17:56.794983 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53): perf score=11.118625
I20260812 06:17:56.850073 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.055s	user 0.018s	sys 0.031s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":22566,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:17:56.850646 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53): perf score=2.188937
I20260812 06:17:56.863608 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.013s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4041,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:56.864131 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53): perf score=2.188937
I20260812 06:17:56.874980 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3934,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:56.875687 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling MajorDeltaCompactionOp(27388575d3284ebeb8c96e0a1c1a6c53): perf score=1.000000
I20260812 06:17:57.066365 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: MajorDeltaCompactionOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.190s	user 0.132s	sys 0.044s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733836,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":689,"lbm_read_time_us":14032,"lbm_reads_lt_1ms":573,"lbm_write_time_us":35317,"lbm_writes_lt_1ms":543,"mutex_wait_us":314,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":2500}
I20260812 06:17:57.066955 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53): perf score=14.095187
I20260812 06:17:57.123610 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.057s	user 0.020s	sys 0.032s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25469,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:17:57.124251 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53): perf score=2.188937
I20260812 06:17:57.136935 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.012s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4987,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:57.137537 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling FlushMRSOp(27388575d3284ebeb8c96e0a1c1a6c53): perf score=1.000000
I20260812 06:17:57.169783 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: FlushMRSOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.032s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":75,"dirs.run_cpu_time_us":513,"dirs.run_wall_time_us":2020,"drs_written":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2011,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:57.170768 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling LogGCOp(27388575d3284ebeb8c96e0a1c1a6c53): free 112692366 bytes of WAL
I20260812 06:17:57.171054 28144 log_reader.cc:385] T 27388575d3284ebeb8c96e0a1c1a6c53: removed 11 log segments from log reader
I20260812 06:17:57.171124 28144 log.cc:1079] T 27388575d3284ebeb8c96e0a1c1a6c53 P 92ede8811f3b4136aaa60b7dc86dbd46: Deleting log segment in path: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473644184-28026-0/minicluster-data/ts-0-root/wals/27388575d3284ebeb8c96e0a1c1a6c53/wal-000000015 (ops 71-75)
I20260812 06:17:57.171167 28144 log.cc:1079] T 27388575d3284ebeb8c96e0a1c1a6c53 P 92ede8811f3b4136aaa60b7dc86dbd46: Deleting log segment in path: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473644184-28026-0/minicluster-data/ts-0-root/wals/27388575d3284ebeb8c96e0a1c1a6c53/wal-000000016 (ops 76-80)
I20260812 06:17:57.171191 28144 log.cc:1079] T 27388575d3284ebeb8c96e0a1c1a6c53 P 92ede8811f3b4136aaa60b7dc86dbd46: Deleting log segment in path: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473644184-28026-0/minicluster-data/ts-0-root/wals/27388575d3284ebeb8c96e0a1c1a6c53/wal-000000017 (ops 81-85)
I20260812 06:17:57.171214 28144 log.cc:1079] T 27388575d3284ebeb8c96e0a1c1a6c53 P 92ede8811f3b4136aaa60b7dc86dbd46: Deleting log segment in path: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473644184-28026-0/minicluster-data/ts-0-root/wals/27388575d3284ebeb8c96e0a1c1a6c53/wal-000000018 (ops 86-90)
I20260812 06:17:57.171236 28144 log.cc:1079] T 27388575d3284ebeb8c96e0a1c1a6c53 P 92ede8811f3b4136aaa60b7dc86dbd46: Deleting log segment in path: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473644184-28026-0/minicluster-data/ts-0-root/wals/27388575d3284ebeb8c96e0a1c1a6c53/wal-000000019 (ops 91-95)
I20260812 06:17:57.171260 28144 log.cc:1079] T 27388575d3284ebeb8c96e0a1c1a6c53 P 92ede8811f3b4136aaa60b7dc86dbd46: Deleting log segment in path: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473644184-28026-0/minicluster-data/ts-0-root/wals/27388575d3284ebeb8c96e0a1c1a6c53/wal-000000020 (ops 96-100)
I20260812 06:17:57.171286 28144 log.cc:1079] T 27388575d3284ebeb8c96e0a1c1a6c53 P 92ede8811f3b4136aaa60b7dc86dbd46: Deleting log segment in path: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473644184-28026-0/minicluster-data/ts-0-root/wals/27388575d3284ebeb8c96e0a1c1a6c53/wal-000000021 (ops 101-105)
I20260812 06:17:57.171311 28144 log.cc:1079] T 27388575d3284ebeb8c96e0a1c1a6c53 P 92ede8811f3b4136aaa60b7dc86dbd46: Deleting log segment in path: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473644184-28026-0/minicluster-data/ts-0-root/wals/27388575d3284ebeb8c96e0a1c1a6c53/wal-000000022 (ops 106-110)
I20260812 06:17:57.171334 28144 log.cc:1079] T 27388575d3284ebeb8c96e0a1c1a6c53 P 92ede8811f3b4136aaa60b7dc86dbd46: Deleting log segment in path: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473644184-28026-0/minicluster-data/ts-0-root/wals/27388575d3284ebeb8c96e0a1c1a6c53/wal-000000023 (ops 111-115)
I20260812 06:17:57.171365 28144 log.cc:1079] T 27388575d3284ebeb8c96e0a1c1a6c53 P 92ede8811f3b4136aaa60b7dc86dbd46: Deleting log segment in path: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473644184-28026-0/minicluster-data/ts-0-root/wals/27388575d3284ebeb8c96e0a1c1a6c53/wal-000000024 (ops 116-120)
I20260812 06:17:57.171388 28144 log.cc:1079] T 27388575d3284ebeb8c96e0a1c1a6c53 P 92ede8811f3b4136aaa60b7dc86dbd46: Deleting log segment in path: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473644184-28026-0/minicluster-data/ts-0-root/wals/27388575d3284ebeb8c96e0a1c1a6c53/wal-000000025 (ops 121-125)
I20260812 06:17:57.200359 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: LogGCOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.029s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:17:57.200856 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53): perf score=3.181125
I20260812 06:17:57.228732 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.028s	user 0.013s	sys 0.007s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4966,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:57.229322 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling UndoDeltaBlockGCOp(27388575d3284ebeb8c96e0a1c1a6c53): 463 bytes on disk
I20260812 06:17:57.229929 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: UndoDeltaBlockGCOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":125,"lbm_reads_lt_1ms":4}
I20260812 06:17:57.230516 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53): perf score=2.188937
I20260812 06:17:57.240872 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.010s	user 0.005s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3860,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:57.241458 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling MajorDeltaCompactionOp(27388575d3284ebeb8c96e0a1c1a6c53): perf score=1.000000
I20260812 06:17:57.507740 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: MajorDeltaCompactionOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.266s	user 0.120s	sys 0.134s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32938775,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1162,"lbm_read_time_us":18702,"lbm_reads_lt_1ms":774,"lbm_write_time_us":40397,"lbm_writes_lt_1ms":743,"mutex_wait_us":87,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":17024,"thread_start_us":83,"threads_started":1,"update_count":3500}
I20260812 06:17:57.508641 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53): perf score=18.063937
I20260812 06:17:57.586589 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.078s	user 0.035s	sys 0.032s Metrics: {"bytes_written":20512319,"delete_count":0,"lbm_write_time_us":31999,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":502,"reinsert_count":0,"update_count":2500}
I20260812 06:17:57.587246 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53): perf score=2.188937
I20260812 06:17:57.598508 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4207,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:57.599007 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling MajorDeltaCompactionOp(27388575d3284ebeb8c96e0a1c1a6c53): perf score=1.000000
I20260812 06:17:57.810109 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: MajorDeltaCompactionOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.211s	user 0.138s	sys 0.072s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28836141,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1292,"lbm_read_time_us":15415,"lbm_reads_lt_1ms":672,"lbm_write_time_us":34952,"lbm_writes_lt_1ms":643,"mutex_wait_us":441,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":18944,"update_count":3000}
I20260812 06:17:57.810911 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53): perf score=14.095187
I20260812 06:17:57.866416 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.055s	user 0.033s	sys 0.021s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24346,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:57.867138 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53): perf score=2.188937
I20260812 06:17:57.884791 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.017s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6110,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:57.885499 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling MajorDeltaCompactionOp(27388575d3284ebeb8c96e0a1c1a6c53): perf score=1.000000
I20260812 06:17:58.076314 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: MajorDeltaCompactionOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.190s	user 0.127s	sys 0.061s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":279,"lbm_read_time_us":14226,"lbm_reads_lt_1ms":568,"lbm_write_time_us":32155,"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:17:58.077028 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53): perf score=14.095187
I20260812 06:17:58.149354 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.072s	user 0.033s	sys 0.035s Metrics: {"bytes_written":16409914,"delete_count":0,"lbm_write_time_us":26311,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:58.150130 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53): perf score=2.188937
I20260812 06:17:58.170657 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.020s	user 0.013s	sys 0.006s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":7816,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:58.171450 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling MajorDeltaCompactionOp(27388575d3284ebeb8c96e0a1c1a6c53): perf score=1.000000
I20260812 06:17:58.372310 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: MajorDeltaCompactionOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.201s	user 0.142s	sys 0.047s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733735,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":193,"lbm_read_time_us":14850,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31816,"lbm_writes_lt_1ms":543,"mutex_wait_us":44,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:58.373142 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53): perf score=14.095187
I20260812 06:17:58.436160 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.063s	user 0.024s	sys 0.031s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20803,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:58.436872 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53): perf score=2.188937
I20260812 06:17:58.448659 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4385,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:58.449194 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling MajorDeltaCompactionOp(27388575d3284ebeb8c96e0a1c1a6c53): perf score=1.000000
I20260812 06:17:58.644459 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: MajorDeltaCompactionOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.195s	user 0.127s	sys 0.058s 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":1066,"lbm_read_time_us":16141,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29918,"lbm_writes_lt_1ms":543,"mutex_wait_us":298,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:58.645231 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53): perf score=14.095187
I20260812 06:17:58.711681 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.066s	user 0.033s	sys 0.024s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20250,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:58.712404 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53): perf score=2.188937
I20260812 06:17:58.725162 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.012s	user 0.000s	sys 0.010s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5142,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:58.725857 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling FlushMRSOp(27388575d3284ebeb8c96e0a1c1a6c53): perf score=1.000000
I20260812 06:17:58.793900 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: FlushMRSOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.068s	user 0.045s	sys 0.001s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":66,"dirs.run_cpu_time_us":260,"dirs.run_wall_time_us":2056,"drs_written":1,"lbm_read_time_us":69,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2532,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:58.795043 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling LogGCOp(27388575d3284ebeb8c96e0a1c1a6c53): free 120553624 bytes of WAL
I20260812 06:17:58.795486 28144 log_reader.cc:385] T 27388575d3284ebeb8c96e0a1c1a6c53: removed 12 log segments from log reader
I20260812 06:17:58.795560 28144 log.cc:1079] T 27388575d3284ebeb8c96e0a1c1a6c53 P 92ede8811f3b4136aaa60b7dc86dbd46: Deleting log segment in path: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473644184-28026-0/minicluster-data/ts-0-root/wals/27388575d3284ebeb8c96e0a1c1a6c53/wal-000000026 (ops 126-130)
I20260812 06:17:58.795603 28144 log.cc:1079] T 27388575d3284ebeb8c96e0a1c1a6c53 P 92ede8811f3b4136aaa60b7dc86dbd46: Deleting log segment in path: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473644184-28026-0/minicluster-data/ts-0-root/wals/27388575d3284ebeb8c96e0a1c1a6c53/wal-000000027 (ops 131-134)
I20260812 06:17:58.795699 28144 log.cc:1079] T 27388575d3284ebeb8c96e0a1c1a6c53 P 92ede8811f3b4136aaa60b7dc86dbd46: Deleting log segment in path: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473644184-28026-0/minicluster-data/ts-0-root/wals/27388575d3284ebeb8c96e0a1c1a6c53/wal-000000028 (ops 135-139)
I20260812 06:17:58.795742 28144 log.cc:1079] T 27388575d3284ebeb8c96e0a1c1a6c53 P 92ede8811f3b4136aaa60b7dc86dbd46: Deleting log segment in path: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473644184-28026-0/minicluster-data/ts-0-root/wals/27388575d3284ebeb8c96e0a1c1a6c53/wal-000000029 (ops 140-144)
I20260812 06:17:58.795804 28144 log.cc:1079] T 27388575d3284ebeb8c96e0a1c1a6c53 P 92ede8811f3b4136aaa60b7dc86dbd46: Deleting log segment in path: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473644184-28026-0/minicluster-data/ts-0-root/wals/27388575d3284ebeb8c96e0a1c1a6c53/wal-000000030 (ops 145-148)
I20260812 06:17:58.795837 28144 log.cc:1079] T 27388575d3284ebeb8c96e0a1c1a6c53 P 92ede8811f3b4136aaa60b7dc86dbd46: Deleting log segment in path: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473644184-28026-0/minicluster-data/ts-0-root/wals/27388575d3284ebeb8c96e0a1c1a6c53/wal-000000031 (ops 149-153)
I20260812 06:17:58.795897 28144 log.cc:1079] T 27388575d3284ebeb8c96e0a1c1a6c53 P 92ede8811f3b4136aaa60b7dc86dbd46: Deleting log segment in path: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473644184-28026-0/minicluster-data/ts-0-root/wals/27388575d3284ebeb8c96e0a1c1a6c53/wal-000000032 (ops 154-158)
I20260812 06:17:58.795934 28144 log.cc:1079] T 27388575d3284ebeb8c96e0a1c1a6c53 P 92ede8811f3b4136aaa60b7dc86dbd46: Deleting log segment in path: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473644184-28026-0/minicluster-data/ts-0-root/wals/27388575d3284ebeb8c96e0a1c1a6c53/wal-000000033 (ops 159-163)
I20260812 06:17:58.795979 28144 log.cc:1079] T 27388575d3284ebeb8c96e0a1c1a6c53 P 92ede8811f3b4136aaa60b7dc86dbd46: Deleting log segment in path: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473644184-28026-0/minicluster-data/ts-0-root/wals/27388575d3284ebeb8c96e0a1c1a6c53/wal-000000034 (ops 164-168)
I20260812 06:17:58.796010 28144 log.cc:1079] T 27388575d3284ebeb8c96e0a1c1a6c53 P 92ede8811f3b4136aaa60b7dc86dbd46: Deleting log segment in path: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473644184-28026-0/minicluster-data/ts-0-root/wals/27388575d3284ebeb8c96e0a1c1a6c53/wal-000000035 (ops 169-173)
I20260812 06:17:58.796056 28144 log.cc:1079] T 27388575d3284ebeb8c96e0a1c1a6c53 P 92ede8811f3b4136aaa60b7dc86dbd46: Deleting log segment in path: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473644184-28026-0/minicluster-data/ts-0-root/wals/27388575d3284ebeb8c96e0a1c1a6c53/wal-000000036 (ops 174-178)
I20260812 06:17:58.796092 28144 log.cc:1079] T 27388575d3284ebeb8c96e0a1c1a6c53 P 92ede8811f3b4136aaa60b7dc86dbd46: Deleting log segment in path: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473644184-28026-0/minicluster-data/ts-0-root/wals/27388575d3284ebeb8c96e0a1c1a6c53/wal-000000037 (ops 179-183)
I20260812 06:17:58.828042 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: LogGCOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.033s	user 0.003s	sys 0.027s Metrics: {}
I20260812 06:17:58.828639 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53): perf score=2.188937
I20260812 06:17:58.850858 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.022s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4184709,"delete_count":0,"lbm_write_time_us":6923,"lbm_writes_lt_1ms":105,"reinsert_count":0,"update_count":510}
I20260812 06:17:58.851364 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53): perf score=2.188937
I20260812 06:17:58.863546 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4020608,"delete_count":0,"lbm_write_time_us":4703,"lbm_writes_lt_1ms":101,"reinsert_count":0,"update_count":490}
I20260812 06:17:58.864023 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling MajorDeltaCompactionOp(27388575d3284ebeb8c96e0a1c1a6c53): perf score=1.000000
I20260812 06:17:59.116176 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: MajorDeltaCompactionOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.252s	user 0.133s	sys 0.108s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32938785,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":241,"lbm_read_time_us":17854,"lbm_reads_lt_1ms":774,"lbm_write_time_us":38851,"lbm_writes_lt_1ms":743,"mutex_wait_us":27,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":47872,"thread_start_us":90,"threads_started":1,"update_count":3500}
I20260812 06:17:59.118671 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53): perf score=18.063937
I20260812 06:17:59.188859 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.070s	user 0.031s	sys 0.029s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":28438,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:59.189496 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling UndoDeltaBlockGCOp(27388575d3284ebeb8c96e0a1c1a6c53): 446 bytes on disk
I20260812 06:17:59.190078 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: UndoDeltaBlockGCOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":80,"lbm_reads_lt_1ms":4}
I20260812 06:17:59.190646 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53): perf score=2.188937
I20260812 06:17:59.207232 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: FlushDeltaMemStoresOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.016s	user 0.006s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6249,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:59.207978 28219 maintenance_manager.cc:419] P 92ede8811f3b4136aaa60b7dc86dbd46: Scheduling MajorDeltaCompactionOp(27388575d3284ebeb8c96e0a1c1a6c53): perf score=1.000000
I20260812 06:17:59.311900 28026 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.322s	user 1.950s	sys 0.178s
I20260812 06:17:59.402740 28026 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.090s	user 0.003s	sys 0.000s
I20260812 06:17:59.403466 28026 tablet_server.cc:179] TabletServer@127.27.94.129:0 shutting down...
I20260812 06:17:59.435010 28144 maintenance_manager.cc:643] P 92ede8811f3b4136aaa60b7dc86dbd46: MajorDeltaCompactionOp(27388575d3284ebeb8c96e0a1c1a6c53) complete. Timing: real 0.227s	user 0.150s	sys 0.075s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28836138,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1036,"lbm_read_time_us":16778,"lbm_reads_lt_1ms":668,"lbm_write_time_us":39867,"lbm_writes_lt_1ms":643,"mutex_wait_us":338,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":3000}
I20260812 06:17:59.435883 28026 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:59.436336 28026 tablet_replica.cc:333] T 27388575d3284ebeb8c96e0a1c1a6c53 P 92ede8811f3b4136aaa60b7dc86dbd46: stopping tablet replica
I20260812 06:17:59.436585 28026 raft_consensus.cc:2243] T 27388575d3284ebeb8c96e0a1c1a6c53 P 92ede8811f3b4136aaa60b7dc86dbd46 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:59.436867 28026 raft_consensus.cc:2272] T 27388575d3284ebeb8c96e0a1c1a6c53 P 92ede8811f3b4136aaa60b7dc86dbd46 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:59.466862 28026 tablet_server.cc:196] TabletServer@127.27.94.129:0 shutdown complete.
I20260812 06:17:59.489748 28026 master.cc:562] Master@127.27.94.190:38981 shutting down...
I20260812 06:17:59.494460 28026 raft_consensus.cc:2243] T 00000000000000000000000000000000 P ee1822d54d7b447bb119b6f18c4f45ee [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:59.494688 28026 raft_consensus.cc:2272] T 00000000000000000000000000000000 P ee1822d54d7b447bb119b6f18c4f45ee [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:59.494781 28026 tablet_replica.cc:333] T 00000000000000000000000000000000 P ee1822d54d7b447bb119b6f18c4f45ee: stopping tablet replica
I20260812 06:17:59.507536 28026 master.cc:584] Master@127.27.94.190:38981 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5949 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:17:59.605245 28026 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.27.94.190:41981
I20260812 06:17:59.605849 28026 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:59.608630 28256 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:59.608696 28026 server_base.cc:1061] running on GCE node
W20260812 06:17:59.608691 28257 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:59.608919 28260 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:59.609129 28026 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:59.609200 28026 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:59.609236 28026 hybrid_clock.cc:648] HybridClock initialized: now 1786515479609227 us; error 0 us; skew 500 ppm
I20260812 06:17:59.610335 28026 webserver.cc:533] Webserver started at http://127.27.94.190:38739/ using document root <none> and password file <none>
I20260812 06:17:59.610541 28026 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:59.610620 28026 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:59.610705 28026 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:59.611155 28026 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473644184-28026-0/minicluster-data/master-0-root/instance:
uuid: "073836149167418bb0e3882122208b63"
format_stamp: "Formatted at 2026-08-12 06:17:59 on dist-test-slave-9zdj"
I20260812 06:17:59.612830 28026 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:59.614310 28267 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:59.614632 28026 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:59.614733 28026 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473644184-28026-0/minicluster-data/master-0-root
uuid: "073836149167418bb0e3882122208b63"
format_stamp: "Formatted at 2026-08-12 06:17:59 on dist-test-slave-9zdj"
I20260812 06:17:59.614831 28026 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473644184-28026-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473644184-28026-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473644184-28026-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:59.627936 28026 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:59.628453 28026 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:59.633524 28026 rpc_server.cc:307] RPC server started. Bound to: 127.27.94.190:41981
I20260812 06:17:59.642124 28329 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:59.644150 28328 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.27.94.190:41981 every 8 connection(s)
I20260812 06:17:59.645488 28329 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 073836149167418bb0e3882122208b63: Bootstrap starting.
I20260812 06:17:59.646495 28329 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 073836149167418bb0e3882122208b63: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:59.647696 28329 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 073836149167418bb0e3882122208b63: No bootstrap required, opened a new log
I20260812 06:17:59.648149 28329 raft_consensus.cc:359] T 00000000000000000000000000000000 P 073836149167418bb0e3882122208b63 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "073836149167418bb0e3882122208b63" member_type: VOTER }
I20260812 06:17:59.648392 28329 raft_consensus.cc:385] T 00000000000000000000000000000000 P 073836149167418bb0e3882122208b63 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:59.648471 28329 raft_consensus.cc:740] T 00000000000000000000000000000000 P 073836149167418bb0e3882122208b63 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 073836149167418bb0e3882122208b63, State: Initialized, Role: FOLLOWER
I20260812 06:17:59.648669 28329 consensus_queue.cc:260] T 00000000000000000000000000000000 P 073836149167418bb0e3882122208b63 [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: "073836149167418bb0e3882122208b63" member_type: VOTER }
I20260812 06:17:59.648785 28329 raft_consensus.cc:399] T 00000000000000000000000000000000 P 073836149167418bb0e3882122208b63 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:59.648825 28329 raft_consensus.cc:493] T 00000000000000000000000000000000 P 073836149167418bb0e3882122208b63 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:59.648869 28329 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 073836149167418bb0e3882122208b63 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:59.649681 28329 raft_consensus.cc:515] T 00000000000000000000000000000000 P 073836149167418bb0e3882122208b63 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "073836149167418bb0e3882122208b63" member_type: VOTER }
I20260812 06:17:59.649848 28329 leader_election.cc:304] T 00000000000000000000000000000000 P 073836149167418bb0e3882122208b63 [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: 073836149167418bb0e3882122208b63; no voters: 
I20260812 06:17:59.650091 28329 leader_election.cc:290] T 00000000000000000000000000000000 P 073836149167418bb0e3882122208b63 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:59.650242 28333 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 073836149167418bb0e3882122208b63 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:59.650502 28333 raft_consensus.cc:697] T 00000000000000000000000000000000 P 073836149167418bb0e3882122208b63 [term 1 LEADER]: Becoming Leader. State: Replica: 073836149167418bb0e3882122208b63, State: Running, Role: LEADER
I20260812 06:17:59.650612 28329 sys_catalog.cc:565] T 00000000000000000000000000000000 P 073836149167418bb0e3882122208b63 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:59.650687 28333 consensus_queue.cc:237] T 00000000000000000000000000000000 P 073836149167418bb0e3882122208b63 [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: "073836149167418bb0e3882122208b63" member_type: VOTER }
I20260812 06:17:59.651183 28334 sys_catalog.cc:455] T 00000000000000000000000000000000 P 073836149167418bb0e3882122208b63 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "073836149167418bb0e3882122208b63" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "073836149167418bb0e3882122208b63" member_type: VOTER } }
I20260812 06:17:59.651297 28334 sys_catalog.cc:458] T 00000000000000000000000000000000 P 073836149167418bb0e3882122208b63 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:59.651201 28335 sys_catalog.cc:455] T 00000000000000000000000000000000 P 073836149167418bb0e3882122208b63 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 073836149167418bb0e3882122208b63. Latest consensus state: current_term: 1 leader_uuid: "073836149167418bb0e3882122208b63" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "073836149167418bb0e3882122208b63" member_type: VOTER } }
I20260812 06:17:59.651527 28335 sys_catalog.cc:458] T 00000000000000000000000000000000 P 073836149167418bb0e3882122208b63 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:59.651597 28340 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:59.652549 28340 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:59.652742 28026 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:59.654838 28340 catalog_manager.cc:1383] Generated new cluster ID: e0659d38f5e8497297cfc9d6b0fe39c7
I20260812 06:17:59.654919 28340 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:59.688417 28340 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:59.689165 28340 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:59.697574 28340 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 073836149167418bb0e3882122208b63: Generated new TSK 0
I20260812 06:17:59.697877 28340 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:59.717819 28026 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:59.720274 28356 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:59.720289 28354 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:59.720384 28353 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:59.720643 28026 server_base.cc:1061] running on GCE node
I20260812 06:17:59.720825 28026 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:59.720868 28026 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:59.720884 28026 hybrid_clock.cc:648] HybridClock initialized: now 1786515479720884 us; error 0 us; skew 500 ppm
I20260812 06:17:59.722046 28026 webserver.cc:533] Webserver started at http://127.27.94.129:33809/ using document root <none> and password file <none>
I20260812 06:17:59.722288 28026 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:59.722366 28026 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:59.722447 28026 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:59.722882 28026 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473644184-28026-0/minicluster-data/ts-0-root/instance:
uuid: "1d7926d1230446b7913ae67da9bb4d13"
format_stamp: "Formatted at 2026-08-12 06:17:59 on dist-test-slave-9zdj"
I20260812 06:17:59.724433 28026 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:59.725591 28362 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:59.725952 28026 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:59.726023 28026 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473644184-28026-0/minicluster-data/ts-0-root
uuid: "1d7926d1230446b7913ae67da9bb4d13"
format_stamp: "Formatted at 2026-08-12 06:17:59 on dist-test-slave-9zdj"
I20260812 06:17:59.726132 28026 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473644184-28026-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473644184-28026-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473644184-28026-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:59.735208 28026 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:59.735821 28026 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:59.736181 28026 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:59.736719 28026 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:59.736783 28026 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:59.736851 28026 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:59.736900 28026 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:59.741936 28026 rpc_server.cc:307] RPC server started. Bound to: 127.27.94.129:36967
I20260812 06:17:59.743542 28433 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.27.94.129:36967 every 8 connection(s)
I20260812 06:17:59.753660 28434 heartbeater.cc:344] Connected to a master server at 127.27.94.190:41981
I20260812 06:17:59.753836 28434 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:59.754184 28434 heartbeater.cc:507] Master 127.27.94.190:41981 requested a full tablet report, sending...
I20260812 06:17:59.755174 28286 ts_manager.cc:194] Registered new tserver with Master: 1d7926d1230446b7913ae67da9bb4d13 (127.27.94.129:36967)
I20260812 06:17:59.755174 28026 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012630092s
I20260812 06:17:59.756350 28286 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:34796
I20260812 06:17:59.764132 28286 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:34808:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:17:59.775020 28392 tablet_service.cc:1511] Processing CreateTablet for tablet f7deba2bd5b74eea8601d4db50831a66 (DEFAULT_TABLE table=heavy-update-compaction-test [id=136c93bf23734cb989121fd67c00204d]), partition=
I20260812 06:17:59.775357 28392 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet f7deba2bd5b74eea8601d4db50831a66. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:59.777967 28449 tablet_bootstrap.cc:492] T f7deba2bd5b74eea8601d4db50831a66 P 1d7926d1230446b7913ae67da9bb4d13: Bootstrap starting.
I20260812 06:17:59.779050 28449 tablet_bootstrap.cc:654] T f7deba2bd5b74eea8601d4db50831a66 P 1d7926d1230446b7913ae67da9bb4d13: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:59.780591 28449 tablet_bootstrap.cc:492] T f7deba2bd5b74eea8601d4db50831a66 P 1d7926d1230446b7913ae67da9bb4d13: No bootstrap required, opened a new log
I20260812 06:17:59.780771 28449 ts_tablet_manager.cc:1403] T f7deba2bd5b74eea8601d4db50831a66 P 1d7926d1230446b7913ae67da9bb4d13: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:17:59.781257 28449 raft_consensus.cc:359] T f7deba2bd5b74eea8601d4db50831a66 P 1d7926d1230446b7913ae67da9bb4d13 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1d7926d1230446b7913ae67da9bb4d13" member_type: VOTER last_known_addr { host: "127.27.94.129" port: 36967 } }
I20260812 06:17:59.781384 28449 raft_consensus.cc:385] T f7deba2bd5b74eea8601d4db50831a66 P 1d7926d1230446b7913ae67da9bb4d13 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:59.781448 28449 raft_consensus.cc:740] T f7deba2bd5b74eea8601d4db50831a66 P 1d7926d1230446b7913ae67da9bb4d13 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 1d7926d1230446b7913ae67da9bb4d13, State: Initialized, Role: FOLLOWER
I20260812 06:17:59.781672 28449 consensus_queue.cc:260] T f7deba2bd5b74eea8601d4db50831a66 P 1d7926d1230446b7913ae67da9bb4d13 [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: "1d7926d1230446b7913ae67da9bb4d13" member_type: VOTER last_known_addr { host: "127.27.94.129" port: 36967 } }
I20260812 06:17:59.781783 28449 raft_consensus.cc:399] T f7deba2bd5b74eea8601d4db50831a66 P 1d7926d1230446b7913ae67da9bb4d13 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:59.781868 28449 raft_consensus.cc:493] T f7deba2bd5b74eea8601d4db50831a66 P 1d7926d1230446b7913ae67da9bb4d13 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:59.781937 28449 raft_consensus.cc:3060] T f7deba2bd5b74eea8601d4db50831a66 P 1d7926d1230446b7913ae67da9bb4d13 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:59.782830 28449 raft_consensus.cc:515] T f7deba2bd5b74eea8601d4db50831a66 P 1d7926d1230446b7913ae67da9bb4d13 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1d7926d1230446b7913ae67da9bb4d13" member_type: VOTER last_known_addr { host: "127.27.94.129" port: 36967 } }
I20260812 06:17:59.783010 28449 leader_election.cc:304] T f7deba2bd5b74eea8601d4db50831a66 P 1d7926d1230446b7913ae67da9bb4d13 [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: 1d7926d1230446b7913ae67da9bb4d13; no voters: 
I20260812 06:17:59.783262 28449 leader_election.cc:290] T f7deba2bd5b74eea8601d4db50831a66 P 1d7926d1230446b7913ae67da9bb4d13 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:59.783433 28451 raft_consensus.cc:2804] T f7deba2bd5b74eea8601d4db50831a66 P 1d7926d1230446b7913ae67da9bb4d13 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:59.783708 28434 heartbeater.cc:499] Master 127.27.94.190:41981 was elected leader, sending a full tablet report...
I20260812 06:17:59.783689 28451 raft_consensus.cc:697] T f7deba2bd5b74eea8601d4db50831a66 P 1d7926d1230446b7913ae67da9bb4d13 [term 1 LEADER]: Becoming Leader. State: Replica: 1d7926d1230446b7913ae67da9bb4d13, State: Running, Role: LEADER
I20260812 06:17:59.783699 28449 ts_tablet_manager.cc:1434] T f7deba2bd5b74eea8601d4db50831a66 P 1d7926d1230446b7913ae67da9bb4d13: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:17:59.783979 28451 consensus_queue.cc:237] T f7deba2bd5b74eea8601d4db50831a66 P 1d7926d1230446b7913ae67da9bb4d13 [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: "1d7926d1230446b7913ae67da9bb4d13" member_type: VOTER last_known_addr { host: "127.27.94.129" port: 36967 } }
I20260812 06:17:59.785655 28285 catalog_manager.cc:5719] T f7deba2bd5b74eea8601d4db50831a66 P 1d7926d1230446b7913ae67da9bb4d13 reported cstate change: term changed from 0 to 1, leader changed from <none> to 1d7926d1230446b7913ae67da9bb4d13 (127.27.94.129). New cstate: current_term: 1 leader_uuid: "1d7926d1230446b7913ae67da9bb4d13" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1d7926d1230446b7913ae67da9bb4d13" member_type: VOTER last_known_addr { host: "127.27.94.129" port: 36967 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:59.855302 28026 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.063s	user 0.016s	sys 0.011s
I20260812 06:17:59.994091 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling FlushMRSOp(f7deba2bd5b74eea8601d4db50831a66): perf score=15.086190
I20260812 06:18:00.130473 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: FlushMRSOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.136s	user 0.088s	sys 0.040s Metrics: {"bytes_written":11897249,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":93,"dirs.run_cpu_time_us":203,"dirs.run_wall_time_us":969,"drs_written":1,"lbm_read_time_us":99,"lbm_reads_lt_1ms":4,"lbm_write_time_us":31948,"lbm_writes_lt_1ms":657,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1450}
I20260812 06:18:00.131142 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling LogGCOp(f7deba2bd5b74eea8601d4db50831a66): free 20743880 bytes of WAL
I20260812 06:18:00.131404 28367 log_reader.cc:385] T f7deba2bd5b74eea8601d4db50831a66: removed 2 log segments from log reader
I20260812 06:18:00.131453 28367 log.cc:1079] T f7deba2bd5b74eea8601d4db50831a66 P 1d7926d1230446b7913ae67da9bb4d13: Deleting log segment in path: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473644184-28026-0/minicluster-data/ts-0-root/wals/f7deba2bd5b74eea8601d4db50831a66/wal-000000001 (ops 1-6)
I20260812 06:18:00.131484 28367 log.cc:1079] T f7deba2bd5b74eea8601d4db50831a66 P 1d7926d1230446b7913ae67da9bb4d13: Deleting log segment in path: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473644184-28026-0/minicluster-data/ts-0-root/wals/f7deba2bd5b74eea8601d4db50831a66/wal-000000002 (ops 7-11)
I20260812 06:18:00.136065 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: LogGCOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.005s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:18:00.136484 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling UndoDeltaBlockGCOp(f7deba2bd5b74eea8601d4db50831a66): 12719220 bytes on disk
I20260812 06:18:00.136965 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: UndoDeltaBlockGCOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4}
I20260812 06:18:00.137420 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66): perf score=2.188937
I20260812 06:18:00.155208 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.018s	user 0.008s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":7033,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:00.155678 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling MajorDeltaCompactionOp(f7deba2bd5b74eea8601d4db50831a66): perf score=1.000000
I20260812 06:18:00.302075 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: MajorDeltaCompactionOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.146s	user 0.100s	sys 0.046s Metrics: {"cfile_cache_miss":422,"cfile_cache_miss_bytes":20262035,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":439,"lbm_read_time_us":11258,"lbm_reads_lt_1ms":454,"lbm_write_time_us":24660,"lbm_writes_lt_1ms":433,"mutex_wait_us":36,"peak_mem_usage":49238594,"reinsert_count":0,"spinlock_wait_cycles":22528,"thread_start_us":393,"threads_started":5,"update_count":1950}
I20260812 06:18:00.302935 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66): perf score=10.126437
I20260812 06:18:00.342909 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.040s	user 0.016s	sys 0.019s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15732,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:00.343433 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66): perf score=2.188937
I20260812 06:18:00.367806 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.024s	user 0.007s	sys 0.015s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4809,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:00.368525 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling MajorDeltaCompactionOp(f7deba2bd5b74eea8601d4db50831a66): perf score=1.000000
I20260812 06:18:00.533537 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: MajorDeltaCompactionOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.165s	user 0.092s	sys 0.072s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":210,"lbm_read_time_us":12378,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25543,"lbm_writes_lt_1ms":443,"mutex_wait_us":88,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":23552,"update_count":2000}
I20260812 06:18:00.534622 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66): perf score=10.126437
I20260812 06:18:00.583334 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.046s	user 0.034s	sys 0.010s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19762,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:00.584049 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66): perf score=2.188937
I20260812 06:18:00.601990 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.018s	user 0.014s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6523,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:00.602473 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling MajorDeltaCompactionOp(f7deba2bd5b74eea8601d4db50831a66): perf score=1.000000
I20260812 06:18:00.748839 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: MajorDeltaCompactionOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.146s	user 0.103s	sys 0.041s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":464,"lbm_read_time_us":12535,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27549,"lbm_writes_lt_1ms":443,"mutex_wait_us":63,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:18:00.749640 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66): perf score=11.118625
I20260812 06:18:00.782474 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.033s	user 0.023s	sys 0.008s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14401,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:00.783087 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66): perf score=2.188937
I20260812 06:18:00.797796 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.015s	user 0.007s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5321,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:00.798520 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling MajorDeltaCompactionOp(f7deba2bd5b74eea8601d4db50831a66): perf score=1.000000
I20260812 06:18:00.927621 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: MajorDeltaCompactionOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.129s	user 0.096s	sys 0.033s 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":355,"lbm_read_time_us":8150,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26637,"lbm_writes_lt_1ms":443,"mutex_wait_us":22,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12672,"update_count":2000}
I20260812 06:18:00.928275 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66): perf score=10.126437
I20260812 06:18:00.990036 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.062s	user 0.021s	sys 0.030s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18044,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:00.990731 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66): perf score=2.188937
I20260812 06:18:01.003233 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.012s	user 0.010s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4773,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:01.003918 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling MajorDeltaCompactionOp(f7deba2bd5b74eea8601d4db50831a66): perf score=1.000000
I20260812 06:18:01.179538 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: MajorDeltaCompactionOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.175s	user 0.110s	sys 0.064s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":368,"lbm_read_time_us":13241,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27448,"lbm_writes_lt_1ms":443,"mutex_wait_us":1,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14848,"update_count":2000}
I20260812 06:18:01.180301 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66): perf score=10.126437
I20260812 06:18:01.219434 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.039s	user 0.016s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14473,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:01.220172 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling MajorDeltaCompactionOp(f7deba2bd5b74eea8601d4db50831a66): perf score=1.000000
I20260812 06:18:01.332459 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: MajorDeltaCompactionOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.112s	user 0.085s	sys 0.024s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569746,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":381,"lbm_read_time_us":7423,"lbm_reads_lt_1ms":363,"lbm_write_time_us":19941,"lbm_writes_lt_1ms":343,"mutex_wait_us":36,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":18560,"update_count":1500}
I20260812 06:18:01.333288 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66): perf score=10.126437
I20260812 06:18:01.387352 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.054s	user 0.029s	sys 0.015s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":22526,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:01.387867 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66): perf score=2.188937
I20260812 06:18:01.400342 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4387,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:01.400846 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling MajorDeltaCompactionOp(f7deba2bd5b74eea8601d4db50831a66): perf score=1.000000
I20260812 06:18:01.551935 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: MajorDeltaCompactionOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.151s	user 0.119s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":609,"lbm_read_time_us":10360,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27814,"lbm_writes_lt_1ms":443,"mutex_wait_us":327,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5120,"update_count":2000}
I20260812 06:18:01.552687 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66): perf score=10.126437
I20260812 06:18:01.602558 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.050s	user 0.025s	sys 0.023s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":20661,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:01.603421 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66): perf score=2.188937
I20260812 06:18:01.632376 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.029s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6666,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:01.633216 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66): perf score=2.188937
I20260812 06:18:01.644446 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4246,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:01.645030 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling FlushMRSOp(f7deba2bd5b74eea8601d4db50831a66): perf score=1.000000
I20260812 06:18:01.685279 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: FlushMRSOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.040s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1275443,"cfile_init":1,"dirs.queue_time_us":111,"dirs.run_cpu_time_us":325,"dirs.run_wall_time_us":1756,"drs_written":1,"lbm_read_time_us":81,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2103,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:01.686061 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling LogGCOp(f7deba2bd5b74eea8601d4db50831a66): free 124710247 bytes of WAL
I20260812 06:18:01.686430 28367 log_reader.cc:385] T f7deba2bd5b74eea8601d4db50831a66: removed 12 log segments from log reader
I20260812 06:18:01.686491 28367 log.cc:1079] T f7deba2bd5b74eea8601d4db50831a66 P 1d7926d1230446b7913ae67da9bb4d13: Deleting log segment in path: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473644184-28026-0/minicluster-data/ts-0-root/wals/f7deba2bd5b74eea8601d4db50831a66/wal-000000003 (ops 12-16)
I20260812 06:18:01.686522 28367 log.cc:1079] T f7deba2bd5b74eea8601d4db50831a66 P 1d7926d1230446b7913ae67da9bb4d13: Deleting log segment in path: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473644184-28026-0/minicluster-data/ts-0-root/wals/f7deba2bd5b74eea8601d4db50831a66/wal-000000004 (ops 17-21)
I20260812 06:18:01.686584 28367 log.cc:1079] T f7deba2bd5b74eea8601d4db50831a66 P 1d7926d1230446b7913ae67da9bb4d13: Deleting log segment in path: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473644184-28026-0/minicluster-data/ts-0-root/wals/f7deba2bd5b74eea8601d4db50831a66/wal-000000005 (ops 22-26)
I20260812 06:18:01.686622 28367 log.cc:1079] T f7deba2bd5b74eea8601d4db50831a66 P 1d7926d1230446b7913ae67da9bb4d13: Deleting log segment in path: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473644184-28026-0/minicluster-data/ts-0-root/wals/f7deba2bd5b74eea8601d4db50831a66/wal-000000006 (ops 27-31)
I20260812 06:18:01.686666 28367 log.cc:1079] T f7deba2bd5b74eea8601d4db50831a66 P 1d7926d1230446b7913ae67da9bb4d13: Deleting log segment in path: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473644184-28026-0/minicluster-data/ts-0-root/wals/f7deba2bd5b74eea8601d4db50831a66/wal-000000007 (ops 32-36)
I20260812 06:18:01.686685 28367 log.cc:1079] T f7deba2bd5b74eea8601d4db50831a66 P 1d7926d1230446b7913ae67da9bb4d13: Deleting log segment in path: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473644184-28026-0/minicluster-data/ts-0-root/wals/f7deba2bd5b74eea8601d4db50831a66/wal-000000008 (ops 37-41)
I20260812 06:18:01.686744 28367 log.cc:1079] T f7deba2bd5b74eea8601d4db50831a66 P 1d7926d1230446b7913ae67da9bb4d13: Deleting log segment in path: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473644184-28026-0/minicluster-data/ts-0-root/wals/f7deba2bd5b74eea8601d4db50831a66/wal-000000009 (ops 42-46)
I20260812 06:18:01.686781 28367 log.cc:1079] T f7deba2bd5b74eea8601d4db50831a66 P 1d7926d1230446b7913ae67da9bb4d13: Deleting log segment in path: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473644184-28026-0/minicluster-data/ts-0-root/wals/f7deba2bd5b74eea8601d4db50831a66/wal-000000010 (ops 47-51)
I20260812 06:18:01.686820 28367 log.cc:1079] T f7deba2bd5b74eea8601d4db50831a66 P 1d7926d1230446b7913ae67da9bb4d13: Deleting log segment in path: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473644184-28026-0/minicluster-data/ts-0-root/wals/f7deba2bd5b74eea8601d4db50831a66/wal-000000011 (ops 52-56)
I20260812 06:18:01.686861 28367 log.cc:1079] T f7deba2bd5b74eea8601d4db50831a66 P 1d7926d1230446b7913ae67da9bb4d13: Deleting log segment in path: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473644184-28026-0/minicluster-data/ts-0-root/wals/f7deba2bd5b74eea8601d4db50831a66/wal-000000012 (ops 57-61)
I20260812 06:18:01.686898 28367 log.cc:1079] T f7deba2bd5b74eea8601d4db50831a66 P 1d7926d1230446b7913ae67da9bb4d13: Deleting log segment in path: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473644184-28026-0/minicluster-data/ts-0-root/wals/f7deba2bd5b74eea8601d4db50831a66/wal-000000013 (ops 62-66)
I20260812 06:18:01.686941 28367 log.cc:1079] T f7deba2bd5b74eea8601d4db50831a66 P 1d7926d1230446b7913ae67da9bb4d13: Deleting log segment in path: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473644184-28026-0/minicluster-data/ts-0-root/wals/f7deba2bd5b74eea8601d4db50831a66/wal-000000014 (ops 67-71)
I20260812 06:18:01.717185 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: LogGCOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.031s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:18:01.717723 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66): perf score=3.181125
I20260812 06:18:01.735512 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.018s	user 0.010s	sys 0.001s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":4629,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:01.736013 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66): perf score=2.188937
I20260812 06:18:01.749480 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.013s	user 0.001s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4021,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:01.750605 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling MajorDeltaCompactionOp(f7deba2bd5b74eea8601d4db50831a66): perf score=1.000000
I20260812 06:18:01.997357 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: MajorDeltaCompactionOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.246s	user 0.165s	sys 0.081s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979858,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":576,"lbm_read_time_us":19816,"lbm_reads_lt_1ms":775,"lbm_write_time_us":41915,"lbm_writes_lt_1ms":743,"mutex_wait_us":43,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":11392,"thread_start_us":83,"threads_started":1,"update_count":3500}
I20260812 06:18:02.000977 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling UndoDeltaBlockGCOp(f7deba2bd5b74eea8601d4db50831a66): 481 bytes on disk
I20260812 06:18:02.001670 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: UndoDeltaBlockGCOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":105,"lbm_reads_lt_1ms":4}
I20260812 06:18:02.002543 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66): perf score=15.087375
I20260812 06:18:02.054209 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.051s	user 0.044s	sys 0.007s Metrics: {"bytes_written":16820143,"delete_count":0,"lbm_write_time_us":22816,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:18:02.055104 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66): perf score=2.188937
I20260812 06:18:02.070338 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.015s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4514,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:02.070830 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling MajorDeltaCompactionOp(f7deba2bd5b74eea8601d4db50831a66): perf score=1.000000
I20260812 06:18:02.236676 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: MajorDeltaCompactionOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.166s	user 0.129s	sys 0.033s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774676,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":386,"lbm_read_time_us":10468,"lbm_reads_lt_1ms":564,"lbm_write_time_us":31919,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3840,"update_count":2500}
I20260812 06:18:02.237319 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66): perf score=14.095187
I20260812 06:18:02.287571 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.050s	user 0.027s	sys 0.020s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21932,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:02.288165 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66): perf score=2.188937
I20260812 06:18:02.301337 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.013s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5131,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:02.301875 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling MajorDeltaCompactionOp(f7deba2bd5b74eea8601d4db50831a66): perf score=1.000000
I20260812 06:18:02.474045 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: MajorDeltaCompactionOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.172s	user 0.126s	sys 0.045s 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":1458,"lbm_read_time_us":11242,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29376,"lbm_writes_lt_1ms":543,"mutex_wait_us":455,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11136,"update_count":2500}
I20260812 06:18:02.474939 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66): perf score=14.095187
I20260812 06:18:02.526451 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.051s	user 0.047s	sys 0.000s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":20847,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:02.527158 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling MajorDeltaCompactionOp(f7deba2bd5b74eea8601d4db50831a66): perf score=1.000000
I20260812 06:18:02.684645 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: MajorDeltaCompactionOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.157s	user 0.087s	sys 0.067s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672156,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1748,"lbm_read_time_us":10397,"lbm_reads_lt_1ms":467,"lbm_write_time_us":26849,"lbm_writes_lt_1ms":443,"mutex_wait_us":402,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2000}
I20260812 06:18:02.685488 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66): perf score=11.118625
I20260812 06:18:02.717842 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.032s	user 0.028s	sys 0.004s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":13770,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:02.718518 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66): perf score=2.188937
I20260812 06:18:02.735616 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.017s	user 0.003s	sys 0.012s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6881,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:02.736320 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling MajorDeltaCompactionOp(f7deba2bd5b74eea8601d4db50831a66): perf score=1.000000
I20260812 06:18:02.885116 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: MajorDeltaCompactionOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.149s	user 0.114s	sys 0.032s 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":652,"lbm_read_time_us":11355,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27614,"lbm_writes_lt_1ms":443,"mutex_wait_us":327,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:18:02.886085 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66): perf score=10.126437
I20260812 06:18:02.925595 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.039s	user 0.014s	sys 0.022s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17560,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":1500}
I20260812 06:18:02.926143 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66): perf score=2.188937
I20260812 06:18:02.938820 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.012s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4340,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:02.939431 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling MajorDeltaCompactionOp(f7deba2bd5b74eea8601d4db50831a66): perf score=1.000000
I20260812 06:18:03.071974 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: MajorDeltaCompactionOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.132s	user 0.101s	sys 0.031s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":222,"lbm_read_time_us":9784,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26029,"lbm_writes_lt_1ms":443,"mutex_wait_us":52,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":15104,"update_count":2000}
I20260812 06:18:03.072768 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66): perf score=10.126437
I20260812 06:18:03.117148 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.044s	user 0.022s	sys 0.016s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":18397,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:03.117806 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66): perf score=2.188937
I20260812 06:18:03.129253 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4283,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:03.129848 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling FlushMRSOp(f7deba2bd5b74eea8601d4db50831a66): perf score=1.000000
I20260812 06:18:03.164742 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: FlushMRSOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.035s	user 0.027s	sys 0.005s Metrics: {"bytes_written":1152514,"cfile_init":1,"dirs.queue_time_us":77,"dirs.run_cpu_time_us":226,"dirs.run_wall_time_us":1519,"drs_written":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2095,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:03.165692 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling LogGCOp(f7deba2bd5b74eea8601d4db50831a66): free 112239314 bytes of WAL
I20260812 06:18:03.165939 28367 log_reader.cc:385] T f7deba2bd5b74eea8601d4db50831a66: removed 11 log segments from log reader
I20260812 06:18:03.165985 28367 log.cc:1079] T f7deba2bd5b74eea8601d4db50831a66 P 1d7926d1230446b7913ae67da9bb4d13: Deleting log segment in path: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473644184-28026-0/minicluster-data/ts-0-root/wals/f7deba2bd5b74eea8601d4db50831a66/wal-000000015 (ops 72-76)
I20260812 06:18:03.166042 28367 log.cc:1079] T f7deba2bd5b74eea8601d4db50831a66 P 1d7926d1230446b7913ae67da9bb4d13: Deleting log segment in path: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473644184-28026-0/minicluster-data/ts-0-root/wals/f7deba2bd5b74eea8601d4db50831a66/wal-000000016 (ops 77-80)
I20260812 06:18:03.166090 28367 log.cc:1079] T f7deba2bd5b74eea8601d4db50831a66 P 1d7926d1230446b7913ae67da9bb4d13: Deleting log segment in path: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473644184-28026-0/minicluster-data/ts-0-root/wals/f7deba2bd5b74eea8601d4db50831a66/wal-000000017 (ops 81-85)
I20260812 06:18:03.166137 28367 log.cc:1079] T f7deba2bd5b74eea8601d4db50831a66 P 1d7926d1230446b7913ae67da9bb4d13: Deleting log segment in path: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473644184-28026-0/minicluster-data/ts-0-root/wals/f7deba2bd5b74eea8601d4db50831a66/wal-000000018 (ops 86-90)
I20260812 06:18:03.166179 28367 log.cc:1079] T f7deba2bd5b74eea8601d4db50831a66 P 1d7926d1230446b7913ae67da9bb4d13: Deleting log segment in path: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473644184-28026-0/minicluster-data/ts-0-root/wals/f7deba2bd5b74eea8601d4db50831a66/wal-000000019 (ops 91-95)
I20260812 06:18:03.166221 28367 log.cc:1079] T f7deba2bd5b74eea8601d4db50831a66 P 1d7926d1230446b7913ae67da9bb4d13: Deleting log segment in path: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473644184-28026-0/minicluster-data/ts-0-root/wals/f7deba2bd5b74eea8601d4db50831a66/wal-000000020 (ops 96-100)
I20260812 06:18:03.166265 28367 log.cc:1079] T f7deba2bd5b74eea8601d4db50831a66 P 1d7926d1230446b7913ae67da9bb4d13: Deleting log segment in path: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473644184-28026-0/minicluster-data/ts-0-root/wals/f7deba2bd5b74eea8601d4db50831a66/wal-000000021 (ops 101-105)
I20260812 06:18:03.166303 28367 log.cc:1079] T f7deba2bd5b74eea8601d4db50831a66 P 1d7926d1230446b7913ae67da9bb4d13: Deleting log segment in path: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473644184-28026-0/minicluster-data/ts-0-root/wals/f7deba2bd5b74eea8601d4db50831a66/wal-000000022 (ops 106-110)
I20260812 06:18:03.166343 28367 log.cc:1079] T f7deba2bd5b74eea8601d4db50831a66 P 1d7926d1230446b7913ae67da9bb4d13: Deleting log segment in path: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473644184-28026-0/minicluster-data/ts-0-root/wals/f7deba2bd5b74eea8601d4db50831a66/wal-000000023 (ops 111-115)
I20260812 06:18:03.166383 28367 log.cc:1079] T f7deba2bd5b74eea8601d4db50831a66 P 1d7926d1230446b7913ae67da9bb4d13: Deleting log segment in path: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473644184-28026-0/minicluster-data/ts-0-root/wals/f7deba2bd5b74eea8601d4db50831a66/wal-000000024 (ops 116-120)
I20260812 06:18:03.166425 28367 log.cc:1079] T f7deba2bd5b74eea8601d4db50831a66 P 1d7926d1230446b7913ae67da9bb4d13: Deleting log segment in path: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473644184-28026-0/minicluster-data/ts-0-root/wals/f7deba2bd5b74eea8601d4db50831a66/wal-000000025 (ops 121-125)
I20260812 06:18:03.194335 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: LogGCOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.028s	user 0.000s	sys 0.028s Metrics: {}
I20260812 06:18:03.194917 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66): perf score=2.188937
I20260812 06:18:03.212028 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.017s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5444,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:03.212615 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling LogGCOp(f7deba2bd5b74eea8601d4db50831a66): free 12017991 bytes of WAL
I20260812 06:18:03.212949 28367 log_reader.cc:385] T f7deba2bd5b74eea8601d4db50831a66: removed 1 log segments from log reader
I20260812 06:18:03.213033 28367 log.cc:1079] T f7deba2bd5b74eea8601d4db50831a66 P 1d7926d1230446b7913ae67da9bb4d13: Deleting log segment in path: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473644184-28026-0/minicluster-data/ts-0-root/wals/f7deba2bd5b74eea8601d4db50831a66/wal-000000026 (ops 126-130)
I20260812 06:18:03.215674 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: LogGCOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:18:03.216152 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling UndoDeltaBlockGCOp(f7deba2bd5b74eea8601d4db50831a66): 448 bytes on disk
I20260812 06:18:03.216954 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: UndoDeltaBlockGCOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":88,"lbm_reads_lt_1ms":4}
I20260812 06:18:03.217772 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66): perf score=2.188937
I20260812 06:18:03.236260 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.018s	user 0.008s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7094,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:03.236876 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling MajorDeltaCompactionOp(f7deba2bd5b74eea8601d4db50831a66): perf score=1.000000
I20260812 06:18:03.431105 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: MajorDeltaCompactionOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.194s	user 0.132s	sys 0.059s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877341,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":4609,"lbm_read_time_us":14945,"lbm_reads_lt_1ms":666,"lbm_write_time_us":39872,"lbm_writes_lt_1ms":643,"mutex_wait_us":2093,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":9088,"thread_start_us":104,"threads_started":1,"update_count":3000}
I20260812 06:18:03.431978 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66): perf score=14.095187
I20260812 06:18:03.486613 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.054s	user 0.031s	sys 0.020s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23738,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:03.487177 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66): perf score=2.188937
I20260812 06:18:03.499962 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.013s	user 0.010s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4605,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:03.500516 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling MajorDeltaCompactionOp(f7deba2bd5b74eea8601d4db50831a66): perf score=1.000000
I20260812 06:18:03.680379 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: MajorDeltaCompactionOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.180s	user 0.129s	sys 0.032s 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":751,"lbm_read_time_us":12646,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32064,"lbm_writes_lt_1ms":543,"mutex_wait_us":369,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6784,"update_count":2500}
I20260812 06:18:03.681110 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66): perf score=14.095187
I20260812 06:18:03.743216 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.062s	user 0.018s	sys 0.032s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":25103,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:18:03.743986 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66): perf score=2.188937
I20260812 06:18:03.756191 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4523,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:03.756764 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling MajorDeltaCompactionOp(f7deba2bd5b74eea8601d4db50831a66): perf score=1.000000
I20260812 06:18:03.951628 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: MajorDeltaCompactionOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.195s	user 0.140s	sys 0.048s 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":429,"lbm_read_time_us":13656,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30338,"lbm_writes_lt_1ms":543,"mutex_wait_us":30,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11776,"update_count":2500}
I20260812 06:18:03.952517 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66): perf score=14.095187
I20260812 06:18:04.012326 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.060s	user 0.036s	sys 0.017s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":25418,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:04.012897 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling MajorDeltaCompactionOp(f7deba2bd5b74eea8601d4db50831a66): perf score=1.000000
I20260812 06:18:04.182984 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: MajorDeltaCompactionOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.170s	user 0.127s	sys 0.042s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672158,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":421,"lbm_read_time_us":12042,"lbm_reads_lt_1ms":463,"lbm_write_time_us":28367,"lbm_writes_lt_1ms":443,"mutex_wait_us":50,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":19584,"update_count":2000}
I20260812 06:18:04.183671 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66): perf score=14.095187
I20260812 06:18:04.240514 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.057s	user 0.033s	sys 0.012s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21134,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:04.241214 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66): perf score=2.188937
I20260812 06:18:04.254846 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.013s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4936,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:04.255416 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling MajorDeltaCompactionOp(f7deba2bd5b74eea8601d4db50831a66): perf score=1.000000
I20260812 06:18:04.447196 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: MajorDeltaCompactionOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.192s	user 0.100s	sys 0.084s 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":292,"lbm_read_time_us":12575,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29037,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:04.447805 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66): perf score=14.095187
I20260812 06:18:04.503273 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.055s	user 0.033s	sys 0.019s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24597,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:04.503867 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66): perf score=2.188937
I20260812 06:18:04.521168 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.017s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5608,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:04.521834 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling MajorDeltaCompactionOp(f7deba2bd5b74eea8601d4db50831a66): perf score=1.000000
I20260812 06:18:04.689493 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: MajorDeltaCompactionOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.167s	user 0.101s	sys 0.054s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":239,"lbm_read_time_us":9851,"lbm_reads_lt_1ms":568,"lbm_write_time_us":32018,"lbm_writes_lt_1ms":543,"mutex_wait_us":51,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9984,"update_count":2500}
I20260812 06:18:04.690373 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66): perf score=14.095187
I20260812 06:18:04.745901 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.055s	user 0.037s	sys 0.011s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21752,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:04.746568 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66): perf score=2.188937
I20260812 06:18:04.759851 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.013s	user 0.002s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4933,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:04.760425 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling FlushMRSOp(f7deba2bd5b74eea8601d4db50831a66): perf score=1.000000
I20260812 06:18:04.796073 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: FlushMRSOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.035s	user 0.027s	sys 0.007s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":88,"dirs.run_cpu_time_us":274,"dirs.run_wall_time_us":1810,"drs_written":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1773,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:04.796833 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling LogGCOp(f7deba2bd5b74eea8601d4db50831a66): free 121459753 bytes of WAL
I20260812 06:18:04.797096 28367 log_reader.cc:385] T f7deba2bd5b74eea8601d4db50831a66: removed 12 log segments from log reader
I20260812 06:18:04.797158 28367 log.cc:1079] T f7deba2bd5b74eea8601d4db50831a66 P 1d7926d1230446b7913ae67da9bb4d13: Deleting log segment in path: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473644184-28026-0/minicluster-data/ts-0-root/wals/f7deba2bd5b74eea8601d4db50831a66/wal-000000027 (ops 131-135)
I20260812 06:18:04.797216 28367 log.cc:1079] T f7deba2bd5b74eea8601d4db50831a66 P 1d7926d1230446b7913ae67da9bb4d13: Deleting log segment in path: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473644184-28026-0/minicluster-data/ts-0-root/wals/f7deba2bd5b74eea8601d4db50831a66/wal-000000028 (ops 136-140)
I20260812 06:18:04.797281 28367 log.cc:1079] T f7deba2bd5b74eea8601d4db50831a66 P 1d7926d1230446b7913ae67da9bb4d13: Deleting log segment in path: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473644184-28026-0/minicluster-data/ts-0-root/wals/f7deba2bd5b74eea8601d4db50831a66/wal-000000029 (ops 141-145)
I20260812 06:18:04.797327 28367 log.cc:1079] T f7deba2bd5b74eea8601d4db50831a66 P 1d7926d1230446b7913ae67da9bb4d13: Deleting log segment in path: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473644184-28026-0/minicluster-data/ts-0-root/wals/f7deba2bd5b74eea8601d4db50831a66/wal-000000030 (ops 146-150)
I20260812 06:18:04.797365 28367 log.cc:1079] T f7deba2bd5b74eea8601d4db50831a66 P 1d7926d1230446b7913ae67da9bb4d13: Deleting log segment in path: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473644184-28026-0/minicluster-data/ts-0-root/wals/f7deba2bd5b74eea8601d4db50831a66/wal-000000031 (ops 151-155)
I20260812 06:18:04.797403 28367 log.cc:1079] T f7deba2bd5b74eea8601d4db50831a66 P 1d7926d1230446b7913ae67da9bb4d13: Deleting log segment in path: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473644184-28026-0/minicluster-data/ts-0-root/wals/f7deba2bd5b74eea8601d4db50831a66/wal-000000032 (ops 156-160)
I20260812 06:18:04.797441 28367 log.cc:1079] T f7deba2bd5b74eea8601d4db50831a66 P 1d7926d1230446b7913ae67da9bb4d13: Deleting log segment in path: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473644184-28026-0/minicluster-data/ts-0-root/wals/f7deba2bd5b74eea8601d4db50831a66/wal-000000033 (ops 161-165)
I20260812 06:18:04.797480 28367 log.cc:1079] T f7deba2bd5b74eea8601d4db50831a66 P 1d7926d1230446b7913ae67da9bb4d13: Deleting log segment in path: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473644184-28026-0/minicluster-data/ts-0-root/wals/f7deba2bd5b74eea8601d4db50831a66/wal-000000034 (ops 166-170)
I20260812 06:18:04.797519 28367 log.cc:1079] T f7deba2bd5b74eea8601d4db50831a66 P 1d7926d1230446b7913ae67da9bb4d13: Deleting log segment in path: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473644184-28026-0/minicluster-data/ts-0-root/wals/f7deba2bd5b74eea8601d4db50831a66/wal-000000035 (ops 171-175)
I20260812 06:18:04.797557 28367 log.cc:1079] T f7deba2bd5b74eea8601d4db50831a66 P 1d7926d1230446b7913ae67da9bb4d13: Deleting log segment in path: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473644184-28026-0/minicluster-data/ts-0-root/wals/f7deba2bd5b74eea8601d4db50831a66/wal-000000036 (ops 176-180)
I20260812 06:18:04.797596 28367 log.cc:1079] T f7deba2bd5b74eea8601d4db50831a66 P 1d7926d1230446b7913ae67da9bb4d13: Deleting log segment in path: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473644184-28026-0/minicluster-data/ts-0-root/wals/f7deba2bd5b74eea8601d4db50831a66/wal-000000037 (ops 181-185)
I20260812 06:18:04.797662 28367 log.cc:1079] T f7deba2bd5b74eea8601d4db50831a66 P 1d7926d1230446b7913ae67da9bb4d13: Deleting log segment in path: /tmp/dist-test-taskeBpJyi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473644184-28026-0/minicluster-data/ts-0-root/wals/f7deba2bd5b74eea8601d4db50831a66/wal-000000038 (ops 186-190)
I20260812 06:18:04.828629 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: LogGCOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.032s	user 0.000s	sys 0.031s Metrics: {}
I20260812 06:18:04.829267 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66): perf score=3.181125
I20260812 06:18:04.857326 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.028s	user 0.003s	sys 0.019s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4975,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:04.857955 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66): perf score=2.188937
I20260812 06:18:04.869722 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4296,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:04.870554 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling UndoDeltaBlockGCOp(f7deba2bd5b74eea8601d4db50831a66): 482 bytes on disk
I20260812 06:18:04.871147 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: UndoDeltaBlockGCOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4}
I20260812 06:18:04.871845 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling MajorDeltaCompactionOp(f7deba2bd5b74eea8601d4db50831a66): perf score=1.000000
I20260812 06:18:05.099984 28026 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.245s	user 1.900s	sys 0.185s
I20260812 06:18:05.121861 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: MajorDeltaCompactionOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.250s	user 0.146s	sys 0.103s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979742,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":17624,"lbm_reads_lt_1ms":770,"lbm_write_time_us":44112,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":3500}
I20260812 06:18:05.122566 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66): perf score=14.095187
I20260812 06:18:05.164148 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: FlushDeltaMemStoresOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.041s	user 0.020s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19778,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":4480,"update_count":2000}
I20260812 06:18:05.164825 28436 maintenance_manager.cc:419] P 1d7926d1230446b7913ae67da9bb4d13: Scheduling MajorDeltaCompactionOp(f7deba2bd5b74eea8601d4db50831a66): perf score=1.000000
I20260812 06:18:05.202536 28026 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.102s	user 0.003s	sys 0.000s
I20260812 06:18:05.203187 28026 tablet_server.cc:179] TabletServer@127.27.94.129:0 shutting down...
I20260812 06:18:05.308800 28367 maintenance_manager.cc:643] P 1d7926d1230446b7913ae67da9bb4d13: MajorDeltaCompactionOp(f7deba2bd5b74eea8601d4db50831a66) complete. Timing: real 0.144s	user 0.093s	sys 0.049s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672157,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":393,"lbm_read_time_us":8467,"lbm_reads_lt_1ms":467,"lbm_write_time_us":25349,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":52,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10624,"update_count":2000}
I20260812 06:18:05.309583 28026 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:05.309964 28026 tablet_replica.cc:333] T f7deba2bd5b74eea8601d4db50831a66 P 1d7926d1230446b7913ae67da9bb4d13: stopping tablet replica
I20260812 06:18:05.310139 28026 raft_consensus.cc:2243] T f7deba2bd5b74eea8601d4db50831a66 P 1d7926d1230446b7913ae67da9bb4d13 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:05.310333 28026 raft_consensus.cc:2272] T f7deba2bd5b74eea8601d4db50831a66 P 1d7926d1230446b7913ae67da9bb4d13 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:05.326633 28026 tablet_server.cc:196] TabletServer@127.27.94.129:0 shutdown complete.
I20260812 06:18:05.349786 28026 master.cc:562] Master@127.27.94.190:41981 shutting down...
I20260812 06:18:05.354926 28026 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 073836149167418bb0e3882122208b63 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:05.355176 28026 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 073836149167418bb0e3882122208b63 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:05.355279 28026 tablet_replica.cc:333] T 00000000000000000000000000000000 P 073836149167418bb0e3882122208b63: stopping tablet replica
I20260812 06:18:05.368249 28026 master.cc:584] Master@127.27.94.190:41981 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5856 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11807 ms total)

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