[==========] 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:19:20.100584 28680 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.28.2.62:36423
I20260812 06:19:20.101584 28680 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:19:20.102174 28680 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:20.108582 28687 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:19:20.108793 28690 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:19:20.109002 28680 server_base.cc:1061] running on GCE node
W20260812 06:19:20.109063 28692 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:19:20.109596 28680 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:20.109716 28680 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:19:20.109758 28680 hybrid_clock.cc:648] HybridClock initialized: now 1786515560109755 us; error 0 us; skew 500 ppm
I20260812 06:19:20.111368 28680 webserver.cc:533] Webserver started at http://127.28.2.62:37817/ using document root <none> and password file <none>
I20260812 06:19:20.111874 28680 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:20.111960 28680 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:20.112210 28680 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:20.113838 28680 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560090170-28680-0/minicluster-data/master-0-root/instance:
uuid: "1eba75cd232e47dda548bfc848cc5b0e"
format_stamp: "Formatted at 2026-08-12 06:19:20 on dist-test-slave-j2vl"
I20260812 06:19:20.117054 28680 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.002s	sys 0.001s
I20260812 06:19:20.119050 28709 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:19:20.119915 28680 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:19:20.120054 28680 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560090170-28680-0/minicluster-data/master-0-root
uuid: "1eba75cd232e47dda548bfc848cc5b0e"
format_stamp: "Formatted at 2026-08-12 06:19:20 on dist-test-slave-j2vl"
I20260812 06:19:20.120157 28680 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560090170-28680-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560090170-28680-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560090170-28680-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:19:20.139629 28680 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:20.140193 28680 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:19:20.140364 28680 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:20.147790 28680 rpc_server.cc:307] RPC server started. Bound to: 127.28.2.62:36423
I20260812 06:19:20.147795 28805 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.28.2.62:36423 every 8 connection(s)
I20260812 06:19:20.149895 28806 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:19:20.154937 28806 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 1eba75cd232e47dda548bfc848cc5b0e: Bootstrap starting.
I20260812 06:19:20.157100 28806 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 1eba75cd232e47dda548bfc848cc5b0e: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:20.157989 28806 log.cc:826] T 00000000000000000000000000000000 P 1eba75cd232e47dda548bfc848cc5b0e: Log is configured to *not* fsync() on all Append() calls
I20260812 06:19:20.159489 28806 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 1eba75cd232e47dda548bfc848cc5b0e: No bootstrap required, opened a new log
I20260812 06:19:20.162026 28806 raft_consensus.cc:359] T 00000000000000000000000000000000 P 1eba75cd232e47dda548bfc848cc5b0e [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1eba75cd232e47dda548bfc848cc5b0e" member_type: VOTER }
I20260812 06:19:20.162179 28806 raft_consensus.cc:385] T 00000000000000000000000000000000 P 1eba75cd232e47dda548bfc848cc5b0e [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:20.162217 28806 raft_consensus.cc:740] T 00000000000000000000000000000000 P 1eba75cd232e47dda548bfc848cc5b0e [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 1eba75cd232e47dda548bfc848cc5b0e, State: Initialized, Role: FOLLOWER
I20260812 06:19:20.162773 28806 consensus_queue.cc:260] T 00000000000000000000000000000000 P 1eba75cd232e47dda548bfc848cc5b0e [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: "1eba75cd232e47dda548bfc848cc5b0e" member_type: VOTER }
I20260812 06:19:20.162911 28806 raft_consensus.cc:399] T 00000000000000000000000000000000 P 1eba75cd232e47dda548bfc848cc5b0e [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:20.162956 28806 raft_consensus.cc:493] T 00000000000000000000000000000000 P 1eba75cd232e47dda548bfc848cc5b0e [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:20.163033 28806 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 1eba75cd232e47dda548bfc848cc5b0e [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:20.163741 28806 raft_consensus.cc:515] T 00000000000000000000000000000000 P 1eba75cd232e47dda548bfc848cc5b0e [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1eba75cd232e47dda548bfc848cc5b0e" member_type: VOTER }
I20260812 06:19:20.164091 28806 leader_election.cc:304] T 00000000000000000000000000000000 P 1eba75cd232e47dda548bfc848cc5b0e [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: 1eba75cd232e47dda548bfc848cc5b0e; no voters: 
I20260812 06:19:20.164327 28806 leader_election.cc:290] T 00000000000000000000000000000000 P 1eba75cd232e47dda548bfc848cc5b0e [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:20.164458 28811 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 1eba75cd232e47dda548bfc848cc5b0e [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:20.164736 28811 raft_consensus.cc:697] T 00000000000000000000000000000000 P 1eba75cd232e47dda548bfc848cc5b0e [term 1 LEADER]: Becoming Leader. State: Replica: 1eba75cd232e47dda548bfc848cc5b0e, State: Running, Role: LEADER
I20260812 06:19:20.165198 28811 consensus_queue.cc:237] T 00000000000000000000000000000000 P 1eba75cd232e47dda548bfc848cc5b0e [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: "1eba75cd232e47dda548bfc848cc5b0e" member_type: VOTER }
I20260812 06:19:20.165277 28806 sys_catalog.cc:565] T 00000000000000000000000000000000 P 1eba75cd232e47dda548bfc848cc5b0e [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:20.167129 28813 sys_catalog.cc:455] T 00000000000000000000000000000000 P 1eba75cd232e47dda548bfc848cc5b0e [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "1eba75cd232e47dda548bfc848cc5b0e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1eba75cd232e47dda548bfc848cc5b0e" member_type: VOTER } }
I20260812 06:19:20.167161 28814 sys_catalog.cc:455] T 00000000000000000000000000000000 P 1eba75cd232e47dda548bfc848cc5b0e [sys.catalog]: SysCatalogTable state changed. Reason: New leader 1eba75cd232e47dda548bfc848cc5b0e. Latest consensus state: current_term: 1 leader_uuid: "1eba75cd232e47dda548bfc848cc5b0e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1eba75cd232e47dda548bfc848cc5b0e" member_type: VOTER } }
I20260812 06:19:20.167254 28813 sys_catalog.cc:458] T 00000000000000000000000000000000 P 1eba75cd232e47dda548bfc848cc5b0e [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:20.167281 28814 sys_catalog.cc:458] T 00000000000000000000000000000000 P 1eba75cd232e47dda548bfc848cc5b0e [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:20.167629 28825 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:20.169878 28825 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:20.170163 28680 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:20.174381 28825 catalog_manager.cc:1383] Generated new cluster ID: 803b60b8dc194f54ac3f68ace3bdf5e3
I20260812 06:19:20.174440 28825 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:20.204171 28825 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:20.205054 28825 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:20.211263 28825 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 1eba75cd232e47dda548bfc848cc5b0e: Generated new TSK 0
I20260812 06:19:20.211854 28825 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:20.235014 28680 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:20.237987 28843 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:19:20.237984 28841 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:19:20.238204 28680 server_base.cc:1061] running on GCE node
W20260812 06:19:20.237987 28840 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:19:20.238461 28680 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:20.238529 28680 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:19:20.238557 28680 hybrid_clock.cc:648] HybridClock initialized: now 1786515560238556 us; error 0 us; skew 500 ppm
I20260812 06:19:20.239523 28680 webserver.cc:533] Webserver started at http://127.28.2.1:33537/ using document root <none> and password file <none>
I20260812 06:19:20.239708 28680 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:20.239779 28680 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:20.239856 28680 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:20.240247 28680 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560090170-28680-0/minicluster-data/ts-0-root/instance:
uuid: "514a191ac1ce4bdf9348e8ba6fa0a63c"
format_stamp: "Formatted at 2026-08-12 06:19:20 on dist-test-slave-j2vl"
I20260812 06:19:20.241806 28680 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:20.242779 28850 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:19:20.243031 28680 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:20.243104 28680 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560090170-28680-0/minicluster-data/ts-0-root
uuid: "514a191ac1ce4bdf9348e8ba6fa0a63c"
format_stamp: "Formatted at 2026-08-12 06:19:20 on dist-test-slave-j2vl"
I20260812 06:19:20.243191 28680 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560090170-28680-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560090170-28680-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560090170-28680-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:19:20.249732 28680 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:20.250126 28680 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:20.250592 28680 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:20.251425 28680 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:20.251477 28680 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:20.251556 28680 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:20.251598 28680 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:20.258634 28680 rpc_server.cc:307] RPC server started. Bound to: 127.28.2.1:35957
I20260812 06:19:20.258702 28976 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.28.2.1:35957 every 8 connection(s)
I20260812 06:19:20.268759 28978 heartbeater.cc:344] Connected to a master server at 127.28.2.62:36423
I20260812 06:19:20.268996 28978 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:20.269498 28978 heartbeater.cc:507] Master 127.28.2.62:36423 requested a full tablet report, sending...
I20260812 06:19:20.270961 28738 ts_manager.cc:194] Registered new tserver with Master: 514a191ac1ce4bdf9348e8ba6fa0a63c (127.28.2.1:35957)
I20260812 06:19:20.271564 28680 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012322559s
I20260812 06:19:20.272390 28738 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:41432
I20260812 06:19:20.281031 28738 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:41438:
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:19:20.295068 28907 tablet_service.cc:1511] Processing CreateTablet for tablet dfa425c1c7234bb6972a78bd6b5df7af (DEFAULT_TABLE table=heavy-update-compaction-test [id=fa0c844e45474610ad67b19b371803b2]), partition=
I20260812 06:19:20.295475 28907 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet dfa425c1c7234bb6972a78bd6b5df7af. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:20.298182 28997 tablet_bootstrap.cc:492] T dfa425c1c7234bb6972a78bd6b5df7af P 514a191ac1ce4bdf9348e8ba6fa0a63c: Bootstrap starting.
I20260812 06:19:20.299331 28997 tablet_bootstrap.cc:654] T dfa425c1c7234bb6972a78bd6b5df7af P 514a191ac1ce4bdf9348e8ba6fa0a63c: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:20.300616 28997 tablet_bootstrap.cc:492] T dfa425c1c7234bb6972a78bd6b5df7af P 514a191ac1ce4bdf9348e8ba6fa0a63c: No bootstrap required, opened a new log
I20260812 06:19:20.300719 28997 ts_tablet_manager.cc:1403] T dfa425c1c7234bb6972a78bd6b5df7af P 514a191ac1ce4bdf9348e8ba6fa0a63c: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:19:20.301203 28997 raft_consensus.cc:359] T dfa425c1c7234bb6972a78bd6b5df7af P 514a191ac1ce4bdf9348e8ba6fa0a63c [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "514a191ac1ce4bdf9348e8ba6fa0a63c" member_type: VOTER last_known_addr { host: "127.28.2.1" port: 35957 } }
I20260812 06:19:20.301369 28997 raft_consensus.cc:385] T dfa425c1c7234bb6972a78bd6b5df7af P 514a191ac1ce4bdf9348e8ba6fa0a63c [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:20.301421 28997 raft_consensus.cc:740] T dfa425c1c7234bb6972a78bd6b5df7af P 514a191ac1ce4bdf9348e8ba6fa0a63c [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 514a191ac1ce4bdf9348e8ba6fa0a63c, State: Initialized, Role: FOLLOWER
I20260812 06:19:20.301558 28997 consensus_queue.cc:260] T dfa425c1c7234bb6972a78bd6b5df7af P 514a191ac1ce4bdf9348e8ba6fa0a63c [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: "514a191ac1ce4bdf9348e8ba6fa0a63c" member_type: VOTER last_known_addr { host: "127.28.2.1" port: 35957 } }
I20260812 06:19:20.301673 28997 raft_consensus.cc:399] T dfa425c1c7234bb6972a78bd6b5df7af P 514a191ac1ce4bdf9348e8ba6fa0a63c [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:20.301712 28997 raft_consensus.cc:493] T dfa425c1c7234bb6972a78bd6b5df7af P 514a191ac1ce4bdf9348e8ba6fa0a63c [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:20.301754 28997 raft_consensus.cc:3060] T dfa425c1c7234bb6972a78bd6b5df7af P 514a191ac1ce4bdf9348e8ba6fa0a63c [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:20.302666 28997 raft_consensus.cc:515] T dfa425c1c7234bb6972a78bd6b5df7af P 514a191ac1ce4bdf9348e8ba6fa0a63c [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "514a191ac1ce4bdf9348e8ba6fa0a63c" member_type: VOTER last_known_addr { host: "127.28.2.1" port: 35957 } }
I20260812 06:19:20.302840 28997 leader_election.cc:304] T dfa425c1c7234bb6972a78bd6b5df7af P 514a191ac1ce4bdf9348e8ba6fa0a63c [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: 514a191ac1ce4bdf9348e8ba6fa0a63c; no voters: 
I20260812 06:19:20.303059 28997 leader_election.cc:290] T dfa425c1c7234bb6972a78bd6b5df7af P 514a191ac1ce4bdf9348e8ba6fa0a63c [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:20.303187 28999 raft_consensus.cc:2804] T dfa425c1c7234bb6972a78bd6b5df7af P 514a191ac1ce4bdf9348e8ba6fa0a63c [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:20.303418 28997 ts_tablet_manager.cc:1434] T dfa425c1c7234bb6972a78bd6b5df7af P 514a191ac1ce4bdf9348e8ba6fa0a63c: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:19:20.303480 28999 raft_consensus.cc:697] T dfa425c1c7234bb6972a78bd6b5df7af P 514a191ac1ce4bdf9348e8ba6fa0a63c [term 1 LEADER]: Becoming Leader. State: Replica: 514a191ac1ce4bdf9348e8ba6fa0a63c, State: Running, Role: LEADER
I20260812 06:19:20.303887 28978 heartbeater.cc:499] Master 127.28.2.62:36423 was elected leader, sending a full tablet report...
I20260812 06:19:20.303671 28999 consensus_queue.cc:237] T dfa425c1c7234bb6972a78bd6b5df7af P 514a191ac1ce4bdf9348e8ba6fa0a63c [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: "514a191ac1ce4bdf9348e8ba6fa0a63c" member_type: VOTER last_known_addr { host: "127.28.2.1" port: 35957 } }
I20260812 06:19:20.306820 28738 catalog_manager.cc:5719] T dfa425c1c7234bb6972a78bd6b5df7af P 514a191ac1ce4bdf9348e8ba6fa0a63c reported cstate change: term changed from 0 to 1, leader changed from <none> to 514a191ac1ce4bdf9348e8ba6fa0a63c (127.28.2.1). New cstate: current_term: 1 leader_uuid: "514a191ac1ce4bdf9348e8ba6fa0a63c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "514a191ac1ce4bdf9348e8ba6fa0a63c" member_type: VOTER last_known_addr { host: "127.28.2.1" port: 35957 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:20.371295 28680 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.055s	user 0.022s	sys 0.004s
I20260812 06:19:20.509764 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling FlushMRSOp(dfa425c1c7234bb6972a78bd6b5df7af): perf score=19.054940
I20260812 06:19:20.682884 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: FlushMRSOp(dfa425c1c7234bb6972a78bd6b5df7af) complete. Timing: real 0.173s	user 0.125s	sys 0.044s Metrics: {"bytes_written":12307492,"cfile_init":1,"compiler_manager_pool.queue_time_us":287,"delete_count":0,"dirs.queue_time_us":33,"dirs.run_cpu_time_us":195,"dirs.run_wall_time_us":912,"drs_written":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4,"lbm_write_time_us":45159,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":756,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":188,"threads_started":1,"update_count":1500}
I20260812 06:19:20.684268 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling LogGCOp(dfa425c1c7234bb6972a78bd6b5df7af): free 20743880 bytes of WAL
I20260812 06:19:20.684574 28858 log_reader.cc:385] T dfa425c1c7234bb6972a78bd6b5df7af: removed 2 log segments from log reader
I20260812 06:19:20.684648 28858 log.cc:1079] T dfa425c1c7234bb6972a78bd6b5df7af P 514a191ac1ce4bdf9348e8ba6fa0a63c: Deleting log segment in path: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560090170-28680-0/minicluster-data/ts-0-root/wals/dfa425c1c7234bb6972a78bd6b5df7af/wal-000000001 (ops 1-6)
I20260812 06:19:20.684715 28858 log.cc:1079] T dfa425c1c7234bb6972a78bd6b5df7af P 514a191ac1ce4bdf9348e8ba6fa0a63c: Deleting log segment in path: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560090170-28680-0/minicluster-data/ts-0-root/wals/dfa425c1c7234bb6972a78bd6b5df7af/wal-000000002 (ops 7-11)
I20260812 06:19:20.690295 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: LogGCOp(dfa425c1c7234bb6972a78bd6b5df7af) complete. Timing: real 0.006s	user 0.000s	sys 0.005s Metrics: {}
I20260812 06:19:20.690682 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af): perf score=2.188937
I20260812 06:19:20.706746 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af) complete. Timing: real 0.016s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5172,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:20.707401 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling MajorDeltaCompactionOp(dfa425c1c7234bb6972a78bd6b5df7af): perf score=1.000000
I20260812 06:19:20.866732 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: MajorDeltaCompactionOp(dfa425c1c7234bb6972a78bd6b5df7af) complete. Timing: real 0.159s	user 0.121s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":730,"lbm_read_time_us":8091,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23660,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":315,"threads_started":5,"update_count":2000}
I20260812 06:19:20.867379 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling UndoDeltaBlockGCOp(dfa425c1c7234bb6972a78bd6b5df7af): 16411392 bytes on disk
I20260812 06:19:20.867901 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: UndoDeltaBlockGCOp(dfa425c1c7234bb6972a78bd6b5df7af) 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:19:20.868343 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af): perf score=11.118625
I20260812 06:19:20.900803 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af) complete. Timing: real 0.032s	user 0.024s	sys 0.004s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":13957,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:19:20.901460 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af): perf score=2.188937
I20260812 06:19:20.924563 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af) complete. Timing: real 0.023s	user 0.006s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5044,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:20.924993 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af): perf score=2.188937
I20260812 06:19:20.935083 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af) complete. Timing: real 0.010s	user 0.001s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3835,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:20.935516 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling MajorDeltaCompactionOp(dfa425c1c7234bb6972a78bd6b5df7af): perf score=1.000000
I20260812 06:19:21.087760 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: MajorDeltaCompactionOp(dfa425c1c7234bb6972a78bd6b5df7af) complete. Timing: real 0.152s	user 0.123s	sys 0.028s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774801,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":643,"lbm_read_time_us":10611,"lbm_reads_lt_1ms":573,"lbm_write_time_us":32013,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6528,"update_count":2500}
I20260812 06:19:21.088343 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af): perf score=10.126437
I20260812 06:19:21.123688 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af) complete. Timing: real 0.035s	user 0.025s	sys 0.007s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16514,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:21.124284 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af): perf score=2.188937
I20260812 06:19:21.139896 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af) complete. Timing: real 0.015s	user 0.006s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5195,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:21.140527 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling MajorDeltaCompactionOp(dfa425c1c7234bb6972a78bd6b5df7af): perf score=1.000000
I20260812 06:19:21.263950 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: MajorDeltaCompactionOp(dfa425c1c7234bb6972a78bd6b5df7af) complete. Timing: real 0.123s	user 0.098s	sys 0.020s 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":317,"lbm_read_time_us":7211,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22804,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:19:21.264600 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af): perf score=11.118625
I20260812 06:19:21.307248 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af) complete. Timing: real 0.042s	user 0.022s	sys 0.019s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":15561,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:21.307909 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af): perf score=2.188937
I20260812 06:19:21.322109 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5057,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:21.322616 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling MajorDeltaCompactionOp(dfa425c1c7234bb6972a78bd6b5df7af): perf score=1.000000
I20260812 06:19:21.459249 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: MajorDeltaCompactionOp(dfa425c1c7234bb6972a78bd6b5df7af) complete. Timing: real 0.136s	user 0.100s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672267,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":263,"lbm_read_time_us":10096,"lbm_reads_lt_1ms":464,"lbm_write_time_us":22938,"lbm_writes_lt_1ms":443,"mutex_wait_us":50,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":15872,"update_count":2000}
I20260812 06:19:21.459892 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af): perf score=10.126437
I20260812 06:19:21.506894 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af) complete. Timing: real 0.047s	user 0.030s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18502,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:21.507416 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af): perf score=2.188937
I20260812 06:19:21.522396 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af) complete. Timing: real 0.015s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5676,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:21.523015 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling MajorDeltaCompactionOp(dfa425c1c7234bb6972a78bd6b5df7af): perf score=1.000000
I20260812 06:19:21.653501 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: MajorDeltaCompactionOp(dfa425c1c7234bb6972a78bd6b5df7af) complete. Timing: real 0.130s	user 0.117s	sys 0.012s 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":701,"lbm_read_time_us":10983,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23218,"lbm_writes_lt_1ms":443,"mutex_wait_us":98,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":573056,"update_count":2000}
I20260812 06:19:21.653970 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af): perf score=10.126437
I20260812 06:19:21.697510 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af) complete. Timing: real 0.043s	user 0.021s	sys 0.021s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18550,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:21.698019 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af): perf score=2.188937
I20260812 06:19:21.707942 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3832,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:21.709172 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling MajorDeltaCompactionOp(dfa425c1c7234bb6972a78bd6b5df7af): perf score=1.000000
I20260812 06:19:21.837612 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: MajorDeltaCompactionOp(dfa425c1c7234bb6972a78bd6b5df7af) complete. Timing: real 0.128s	user 0.102s	sys 0.025s 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":1311,"lbm_read_time_us":9273,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26299,"lbm_writes_lt_1ms":443,"mutex_wait_us":293,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11904,"update_count":2000}
I20260812 06:19:21.838375 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af): perf score=10.126437
I20260812 06:19:21.878734 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af) complete. Timing: real 0.040s	user 0.019s	sys 0.013s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":14614,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:21.879344 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af): perf score=2.188937
I20260812 06:19:21.890553 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4115,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:21.891050 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling FlushMRSOp(dfa425c1c7234bb6972a78bd6b5df7af): perf score=1.000000
I20260812 06:19:21.920300 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: FlushMRSOp(dfa425c1c7234bb6972a78bd6b5df7af) complete. Timing: real 0.029s	user 0.027s	sys 0.001s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":63,"dirs.run_cpu_time_us":242,"dirs.run_wall_time_us":1369,"drs_written":1,"lbm_read_time_us":43,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1380,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:19:21.921056 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling LogGCOp(dfa425c1c7234bb6972a78bd6b5df7af): free 120100322 bytes of WAL
I20260812 06:19:21.921284 28858 log_reader.cc:385] T dfa425c1c7234bb6972a78bd6b5df7af: removed 12 log segments from log reader
I20260812 06:19:21.921350 28858 log.cc:1079] T dfa425c1c7234bb6972a78bd6b5df7af P 514a191ac1ce4bdf9348e8ba6fa0a63c: Deleting log segment in path: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560090170-28680-0/minicluster-data/ts-0-root/wals/dfa425c1c7234bb6972a78bd6b5df7af/wal-000000003 (ops 12-16)
I20260812 06:19:21.921424 28858 log.cc:1079] T dfa425c1c7234bb6972a78bd6b5df7af P 514a191ac1ce4bdf9348e8ba6fa0a63c: Deleting log segment in path: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560090170-28680-0/minicluster-data/ts-0-root/wals/dfa425c1c7234bb6972a78bd6b5df7af/wal-000000004 (ops 17-21)
I20260812 06:19:21.921482 28858 log.cc:1079] T dfa425c1c7234bb6972a78bd6b5df7af P 514a191ac1ce4bdf9348e8ba6fa0a63c: Deleting log segment in path: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560090170-28680-0/minicluster-data/ts-0-root/wals/dfa425c1c7234bb6972a78bd6b5df7af/wal-000000005 (ops 22-26)
I20260812 06:19:21.921523 28858 log.cc:1079] T dfa425c1c7234bb6972a78bd6b5df7af P 514a191ac1ce4bdf9348e8ba6fa0a63c: Deleting log segment in path: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560090170-28680-0/minicluster-data/ts-0-root/wals/dfa425c1c7234bb6972a78bd6b5df7af/wal-000000006 (ops 27-30)
I20260812 06:19:21.921559 28858 log.cc:1079] T dfa425c1c7234bb6972a78bd6b5df7af P 514a191ac1ce4bdf9348e8ba6fa0a63c: Deleting log segment in path: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560090170-28680-0/minicluster-data/ts-0-root/wals/dfa425c1c7234bb6972a78bd6b5df7af/wal-000000007 (ops 31-35)
I20260812 06:19:21.921595 28858 log.cc:1079] T dfa425c1c7234bb6972a78bd6b5df7af P 514a191ac1ce4bdf9348e8ba6fa0a63c: Deleting log segment in path: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560090170-28680-0/minicluster-data/ts-0-root/wals/dfa425c1c7234bb6972a78bd6b5df7af/wal-000000008 (ops 36-40)
I20260812 06:19:21.921633 28858 log.cc:1079] T dfa425c1c7234bb6972a78bd6b5df7af P 514a191ac1ce4bdf9348e8ba6fa0a63c: Deleting log segment in path: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560090170-28680-0/minicluster-data/ts-0-root/wals/dfa425c1c7234bb6972a78bd6b5df7af/wal-000000009 (ops 41-44)
I20260812 06:19:21.921670 28858 log.cc:1079] T dfa425c1c7234bb6972a78bd6b5df7af P 514a191ac1ce4bdf9348e8ba6fa0a63c: Deleting log segment in path: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560090170-28680-0/minicluster-data/ts-0-root/wals/dfa425c1c7234bb6972a78bd6b5df7af/wal-000000010 (ops 45-49)
I20260812 06:19:21.921705 28858 log.cc:1079] T dfa425c1c7234bb6972a78bd6b5df7af P 514a191ac1ce4bdf9348e8ba6fa0a63c: Deleting log segment in path: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560090170-28680-0/minicluster-data/ts-0-root/wals/dfa425c1c7234bb6972a78bd6b5df7af/wal-000000011 (ops 50-54)
I20260812 06:19:21.921742 28858 log.cc:1079] T dfa425c1c7234bb6972a78bd6b5df7af P 514a191ac1ce4bdf9348e8ba6fa0a63c: Deleting log segment in path: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560090170-28680-0/minicluster-data/ts-0-root/wals/dfa425c1c7234bb6972a78bd6b5df7af/wal-000000012 (ops 55-58)
I20260812 06:19:21.921777 28858 log.cc:1079] T dfa425c1c7234bb6972a78bd6b5df7af P 514a191ac1ce4bdf9348e8ba6fa0a63c: Deleting log segment in path: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560090170-28680-0/minicluster-data/ts-0-root/wals/dfa425c1c7234bb6972a78bd6b5df7af/wal-000000013 (ops 59-63)
I20260812 06:19:21.921816 28858 log.cc:1079] T dfa425c1c7234bb6972a78bd6b5df7af P 514a191ac1ce4bdf9348e8ba6fa0a63c: Deleting log segment in path: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560090170-28680-0/minicluster-data/ts-0-root/wals/dfa425c1c7234bb6972a78bd6b5df7af/wal-000000014 (ops 64-68)
I20260812 06:19:21.949172 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: LogGCOp(dfa425c1c7234bb6972a78bd6b5df7af) complete. Timing: real 0.028s	user 0.001s	sys 0.023s Metrics: {}
I20260812 06:19:21.949633 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af): perf score=3.181125
I20260812 06:19:21.967042 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af) complete. Timing: real 0.017s	user 0.007s	sys 0.009s Metrics: {"bytes_written":4882121,"delete_count":0,"lbm_write_time_us":7297,"lbm_writes_lt_1ms":122,"reinsert_count":0,"update_count":595}
I20260812 06:19:21.967438 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling UndoDeltaBlockGCOp(dfa425c1c7234bb6972a78bd6b5df7af): 463 bytes on disk
I20260812 06:19:21.967849 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: UndoDeltaBlockGCOp(dfa425c1c7234bb6972a78bd6b5df7af) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4}
I20260812 06:19:21.968354 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af): perf score=2.188937
I20260812 06:19:21.978437 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af) complete. Timing: real 0.010s	user 0.005s	sys 0.003s Metrics: {"bytes_written":3323180,"delete_count":0,"lbm_write_time_us":3207,"lbm_writes_lt_1ms":84,"reinsert_count":0,"update_count":405}
I20260812 06:19:21.979455 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling MajorDeltaCompactionOp(dfa425c1c7234bb6972a78bd6b5df7af): perf score=1.000000
I20260812 06:19:22.164137 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: MajorDeltaCompactionOp(dfa425c1c7234bb6972a78bd6b5df7af) complete. Timing: real 0.185s	user 0.121s	sys 0.052s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877320,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":533,"lbm_read_time_us":12122,"lbm_reads_lt_1ms":674,"lbm_write_time_us":35142,"lbm_writes_lt_1ms":643,"mutex_wait_us":169,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":8832,"thread_start_us":101,"threads_started":1,"update_count":3000}
I20260812 06:19:22.164790 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af): perf score=14.095187
I20260812 06:19:22.213902 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af) complete. Timing: real 0.048s	user 0.025s	sys 0.023s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":22449,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:19:22.214450 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af): perf score=2.188937
I20260812 06:19:22.229156 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af) complete. Timing: real 0.015s	user 0.002s	sys 0.009s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4808,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:22.229677 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling MajorDeltaCompactionOp(dfa425c1c7234bb6972a78bd6b5df7af): perf score=1.000000
I20260812 06:19:22.371969 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: MajorDeltaCompactionOp(dfa425c1c7234bb6972a78bd6b5df7af) complete. Timing: real 0.142s	user 0.104s	sys 0.037s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774686,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":751,"lbm_read_time_us":8458,"lbm_reads_lt_1ms":564,"lbm_write_time_us":28049,"lbm_writes_lt_1ms":543,"mutex_wait_us":25,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8192,"update_count":2500}
I20260812 06:19:22.372727 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af): perf score=14.095187
I20260812 06:19:22.433931 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af) complete. Timing: real 0.061s	user 0.026s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23625,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:19:22.434434 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af): perf score=2.188937
I20260812 06:19:22.445449 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af) complete. Timing: real 0.011s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3927,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:22.445940 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling MajorDeltaCompactionOp(dfa425c1c7234bb6972a78bd6b5df7af): perf score=1.000000
I20260812 06:19:22.620586 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: MajorDeltaCompactionOp(dfa425c1c7234bb6972a78bd6b5df7af) complete. Timing: real 0.174s	user 0.088s	sys 0.076s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":971,"lbm_read_time_us":11658,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29950,"lbm_writes_lt_1ms":543,"mutex_wait_us":276,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8832,"update_count":2500}
I20260812 06:19:22.621059 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af): perf score=14.095187
I20260812 06:19:22.676167 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af) complete. Timing: real 0.055s	user 0.032s	sys 0.008s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17794,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:22.676666 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af): perf score=2.188937
I20260812 06:19:22.687577 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af) complete. Timing: real 0.011s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4072,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:22.688165 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling MajorDeltaCompactionOp(dfa425c1c7234bb6972a78bd6b5df7af): perf score=1.000000
I20260812 06:19:22.853860 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: MajorDeltaCompactionOp(dfa425c1c7234bb6972a78bd6b5df7af) complete. Timing: real 0.166s	user 0.138s	sys 0.027s 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":152,"lbm_read_time_us":12676,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30240,"lbm_writes_lt_1ms":543,"mutex_wait_us":35,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":16000,"update_count":2500}
I20260812 06:19:22.854550 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af): perf score=10.126437
I20260812 06:19:22.888556 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af) complete. Timing: real 0.034s	user 0.015s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14531,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:22.889148 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af): perf score=2.188937
I20260812 06:19:22.910593 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af) complete. Timing: real 0.021s	user 0.009s	sys 0.011s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4828,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:22.911145 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling MajorDeltaCompactionOp(dfa425c1c7234bb6972a78bd6b5df7af): perf score=1.000000
I20260812 06:19:23.072574 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: MajorDeltaCompactionOp(dfa425c1c7234bb6972a78bd6b5df7af) complete. Timing: real 0.161s	user 0.101s	sys 0.052s 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":678,"lbm_read_time_us":9707,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26825,"lbm_writes_lt_1ms":443,"mutex_wait_us":289,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":16512,"update_count":2000}
I20260812 06:19:23.073150 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af): perf score=11.118625
I20260812 06:19:23.110369 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af) complete. Timing: real 0.037s	user 0.029s	sys 0.007s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16021,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:23.110970 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af): perf score=2.188937
I20260812 06:19:23.138216 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af) complete. Timing: real 0.027s	user 0.014s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5825,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:23.138697 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af): perf score=2.188937
I20260812 06:19:23.149624 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4176,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:23.150159 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling MajorDeltaCompactionOp(dfa425c1c7234bb6972a78bd6b5df7af): perf score=1.000000
I20260812 06:19:23.313470 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: MajorDeltaCompactionOp(dfa425c1c7234bb6972a78bd6b5df7af) complete. Timing: real 0.163s	user 0.117s	sys 0.036s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774798,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":455,"lbm_read_time_us":11111,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30880,"lbm_writes_lt_1ms":543,"mutex_wait_us":21,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8064,"update_count":2500}
I20260812 06:19:23.314031 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af): perf score=14.095187
I20260812 06:19:23.365530 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af) complete. Timing: real 0.051s	user 0.025s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21690,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":2944,"update_count":2000}
I20260812 06:19:23.366102 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af): perf score=2.188937
I20260812 06:19:23.376935 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3884,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:23.377710 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling FlushMRSOp(dfa425c1c7234bb6972a78bd6b5df7af): perf score=1.000000
I20260812 06:19:23.409729 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: FlushMRSOp(dfa425c1c7234bb6972a78bd6b5df7af) complete. Timing: real 0.032s	user 0.027s	sys 0.005s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":64,"dirs.run_cpu_time_us":245,"dirs.run_wall_time_us":1269,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1584,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:23.410427 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling LogGCOp(dfa425c1c7234bb6972a78bd6b5df7af): free 121006389 bytes of WAL
I20260812 06:19:23.410668 28858 log_reader.cc:385] T dfa425c1c7234bb6972a78bd6b5df7af: removed 12 log segments from log reader
I20260812 06:19:23.410714 28858 log.cc:1079] T dfa425c1c7234bb6972a78bd6b5df7af P 514a191ac1ce4bdf9348e8ba6fa0a63c: Deleting log segment in path: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560090170-28680-0/minicluster-data/ts-0-root/wals/dfa425c1c7234bb6972a78bd6b5df7af/wal-000000015 (ops 69-73)
I20260812 06:19:23.410742 28858 log.cc:1079] T dfa425c1c7234bb6972a78bd6b5df7af P 514a191ac1ce4bdf9348e8ba6fa0a63c: Deleting log segment in path: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560090170-28680-0/minicluster-data/ts-0-root/wals/dfa425c1c7234bb6972a78bd6b5df7af/wal-000000016 (ops 74-78)
I20260812 06:19:23.410806 28858 log.cc:1079] T dfa425c1c7234bb6972a78bd6b5df7af P 514a191ac1ce4bdf9348e8ba6fa0a63c: Deleting log segment in path: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560090170-28680-0/minicluster-data/ts-0-root/wals/dfa425c1c7234bb6972a78bd6b5df7af/wal-000000017 (ops 79-82)
I20260812 06:19:23.410863 28858 log.cc:1079] T dfa425c1c7234bb6972a78bd6b5df7af P 514a191ac1ce4bdf9348e8ba6fa0a63c: Deleting log segment in path: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560090170-28680-0/minicluster-data/ts-0-root/wals/dfa425c1c7234bb6972a78bd6b5df7af/wal-000000018 (ops 83-87)
I20260812 06:19:23.410902 28858 log.cc:1079] T dfa425c1c7234bb6972a78bd6b5df7af P 514a191ac1ce4bdf9348e8ba6fa0a63c: Deleting log segment in path: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560090170-28680-0/minicluster-data/ts-0-root/wals/dfa425c1c7234bb6972a78bd6b5df7af/wal-000000019 (ops 88-92)
I20260812 06:19:23.410962 28858 log.cc:1079] T dfa425c1c7234bb6972a78bd6b5df7af P 514a191ac1ce4bdf9348e8ba6fa0a63c: Deleting log segment in path: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560090170-28680-0/minicluster-data/ts-0-root/wals/dfa425c1c7234bb6972a78bd6b5df7af/wal-000000020 (ops 93-97)
I20260812 06:19:23.410986 28858 log.cc:1079] T dfa425c1c7234bb6972a78bd6b5df7af P 514a191ac1ce4bdf9348e8ba6fa0a63c: Deleting log segment in path: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560090170-28680-0/minicluster-data/ts-0-root/wals/dfa425c1c7234bb6972a78bd6b5df7af/wal-000000021 (ops 98-102)
I20260812 06:19:23.411024 28858 log.cc:1079] T dfa425c1c7234bb6972a78bd6b5df7af P 514a191ac1ce4bdf9348e8ba6fa0a63c: Deleting log segment in path: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560090170-28680-0/minicluster-data/ts-0-root/wals/dfa425c1c7234bb6972a78bd6b5df7af/wal-000000022 (ops 103-107)
I20260812 06:19:23.411063 28858 log.cc:1079] T dfa425c1c7234bb6972a78bd6b5df7af P 514a191ac1ce4bdf9348e8ba6fa0a63c: Deleting log segment in path: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560090170-28680-0/minicluster-data/ts-0-root/wals/dfa425c1c7234bb6972a78bd6b5df7af/wal-000000023 (ops 108-112)
I20260812 06:19:23.411101 28858 log.cc:1079] T dfa425c1c7234bb6972a78bd6b5df7af P 514a191ac1ce4bdf9348e8ba6fa0a63c: Deleting log segment in path: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560090170-28680-0/minicluster-data/ts-0-root/wals/dfa425c1c7234bb6972a78bd6b5df7af/wal-000000024 (ops 113-117)
I20260812 06:19:23.411139 28858 log.cc:1079] T dfa425c1c7234bb6972a78bd6b5df7af P 514a191ac1ce4bdf9348e8ba6fa0a63c: Deleting log segment in path: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560090170-28680-0/minicluster-data/ts-0-root/wals/dfa425c1c7234bb6972a78bd6b5df7af/wal-000000025 (ops 118-122)
I20260812 06:19:23.411175 28858 log.cc:1079] T dfa425c1c7234bb6972a78bd6b5df7af P 514a191ac1ce4bdf9348e8ba6fa0a63c: Deleting log segment in path: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560090170-28680-0/minicluster-data/ts-0-root/wals/dfa425c1c7234bb6972a78bd6b5df7af/wal-000000026 (ops 123-127)
I20260812 06:19:23.437258 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: LogGCOp(dfa425c1c7234bb6972a78bd6b5df7af) complete. Timing: real 0.027s	user 0.004s	sys 0.019s Metrics: {}
I20260812 06:19:23.437716 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af): perf score=5.165500
I20260812 06:19:23.455225 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af) complete. Timing: real 0.017s	user 0.002s	sys 0.013s Metrics: {"bytes_written":7015374,"delete_count":0,"lbm_write_time_us":7244,"lbm_writes_lt_1ms":174,"reinsert_count":0,"update_count":855}
I20260812 06:19:23.455869 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling LogGCOp(dfa425c1c7234bb6972a78bd6b5df7af): free 12018000 bytes of WAL
I20260812 06:19:23.456133 28858 log_reader.cc:385] T dfa425c1c7234bb6972a78bd6b5df7af: removed 1 log segments from log reader
I20260812 06:19:23.456238 28858 log.cc:1079] T dfa425c1c7234bb6972a78bd6b5df7af P 514a191ac1ce4bdf9348e8ba6fa0a63c: Deleting log segment in path: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560090170-28680-0/minicluster-data/ts-0-root/wals/dfa425c1c7234bb6972a78bd6b5df7af/wal-000000027 (ops 128-132)
I20260812 06:19:23.459514 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: LogGCOp(dfa425c1c7234bb6972a78bd6b5df7af) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:19:23.459862 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling UndoDeltaBlockGCOp(dfa425c1c7234bb6972a78bd6b5df7af): 482 bytes on disk
I20260812 06:19:23.460364 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: UndoDeltaBlockGCOp(dfa425c1c7234bb6972a78bd6b5df7af) 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:19:23.467442 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af): perf score=1.000000
I20260812 06:19:23.478139 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af) complete. Timing: real 0.011s	user 0.005s	sys 0.001s Metrics: {"bytes_written":1189877,"delete_count":0,"lbm_write_time_us":1817,"lbm_writes_lt_1ms":32,"reinsert_count":0,"update_count":145}
I20260812 06:19:23.478653 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling MajorDeltaCompactionOp(dfa425c1c7234bb6972a78bd6b5df7af): perf score=1.000000
I20260812 06:19:23.703087 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: MajorDeltaCompactionOp(dfa425c1c7234bb6972a78bd6b5df7af) complete. Timing: real 0.224s	user 0.147s	sys 0.071s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979678,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":574,"lbm_read_time_us":15913,"lbm_reads_lt_1ms":766,"lbm_write_time_us":36335,"lbm_writes_lt_1ms":743,"mutex_wait_us":64,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":1280,"thread_start_us":81,"threads_started":1,"update_count":3500}
I20260812 06:19:23.703859 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af): perf score=18.063937
I20260812 06:19:23.772948 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af) complete. Timing: real 0.069s	user 0.039s	sys 0.019s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":26864,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:23.773615 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af): perf score=2.188937
I20260812 06:19:23.784317 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4203,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:23.784802 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling MajorDeltaCompactionOp(dfa425c1c7234bb6972a78bd6b5df7af): perf score=1.000000
I20260812 06:19:23.988464 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: MajorDeltaCompactionOp(dfa425c1c7234bb6972a78bd6b5df7af) complete. Timing: real 0.203s	user 0.139s	sys 0.064s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877104,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":521,"lbm_read_time_us":15036,"lbm_reads_lt_1ms":672,"lbm_write_time_us":33799,"lbm_writes_lt_1ms":643,"mutex_wait_us":199,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":16128,"update_count":3000}
I20260812 06:19:23.992564 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af): perf score=14.095187
I20260812 06:19:24.048559 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af) complete. Timing: real 0.056s	user 0.031s	sys 0.012s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20299,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:24.048997 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af): perf score=2.188937
I20260812 06:19:24.060168 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4153,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:24.060724 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling MajorDeltaCompactionOp(dfa425c1c7234bb6972a78bd6b5df7af): perf score=1.000000
I20260812 06:19:24.221145 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: MajorDeltaCompactionOp(dfa425c1c7234bb6972a78bd6b5df7af) complete. Timing: real 0.160s	user 0.115s	sys 0.044s 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":203,"lbm_read_time_us":11719,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29374,"lbm_writes_lt_1ms":543,"mutex_wait_us":50,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6272,"update_count":2500}
I20260812 06:19:24.221772 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af): perf score=14.095187
I20260812 06:19:24.280771 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af) complete. Timing: real 0.059s	user 0.025s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19986,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:24.281327 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af): perf score=2.188937
I20260812 06:19:24.291606 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3991,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:24.292049 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling MajorDeltaCompactionOp(dfa425c1c7234bb6972a78bd6b5df7af): perf score=1.000000
I20260812 06:19:24.464947 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: MajorDeltaCompactionOp(dfa425c1c7234bb6972a78bd6b5df7af) complete. Timing: real 0.173s	user 0.110s	sys 0.059s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1571,"lbm_read_time_us":12276,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31328,"lbm_writes_lt_1ms":543,"mutex_wait_us":762,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4352,"update_count":2500}
I20260812 06:19:24.466439 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af): perf score=11.118625
I20260812 06:19:24.501626 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af) complete. Timing: real 0.035s	user 0.027s	sys 0.008s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15062,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:24.502252 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af): perf score=2.188937
I20260812 06:19:24.534000 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af) complete. Timing: real 0.032s	user 0.017s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6694,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:24.534463 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af): perf score=2.188937
I20260812 06:19:24.544744 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af) complete. Timing: real 0.010s	user 0.001s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3953,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:24.545168 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling MajorDeltaCompactionOp(dfa425c1c7234bb6972a78bd6b5df7af): perf score=1.000000
I20260812 06:19:24.725077 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: MajorDeltaCompactionOp(dfa425c1c7234bb6972a78bd6b5df7af) complete. Timing: real 0.180s	user 0.121s	sys 0.049s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774798,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":619,"lbm_read_time_us":11960,"lbm_reads_lt_1ms":573,"lbm_write_time_us":28382,"lbm_writes_lt_1ms":543,"mutex_wait_us":268,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2500}
I20260812 06:19:24.725847 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af): perf score=14.095187
I20260812 06:19:24.787459 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af) complete. Timing: real 0.061s	user 0.031s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20828,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:24.788105 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af): perf score=2.188937
I20260812 06:19:24.798648 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4087,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:24.799129 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling FlushMRSOp(dfa425c1c7234bb6972a78bd6b5df7af): perf score=1.000000
I20260812 06:19:24.846062 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: FlushMRSOp(dfa425c1c7234bb6972a78bd6b5df7af) complete. Timing: real 0.047s	user 0.029s	sys 0.003s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":70,"dirs.run_cpu_time_us":256,"dirs.run_wall_time_us":1400,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1432,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:24.846772 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling LogGCOp(dfa425c1c7234bb6972a78bd6b5df7af): free 104831826 bytes of WAL
I20260812 06:19:24.846997 28858 log_reader.cc:385] T dfa425c1c7234bb6972a78bd6b5df7af: removed 11 log segments from log reader
I20260812 06:19:24.847043 28858 log.cc:1079] T dfa425c1c7234bb6972a78bd6b5df7af P 514a191ac1ce4bdf9348e8ba6fa0a63c: Deleting log segment in path: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560090170-28680-0/minicluster-data/ts-0-root/wals/dfa425c1c7234bb6972a78bd6b5df7af/wal-000000028 (ops 133-137)
I20260812 06:19:24.847074 28858 log.cc:1079] T dfa425c1c7234bb6972a78bd6b5df7af P 514a191ac1ce4bdf9348e8ba6fa0a63c: Deleting log segment in path: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560090170-28680-0/minicluster-data/ts-0-root/wals/dfa425c1c7234bb6972a78bd6b5df7af/wal-000000029 (ops 138-142)
I20260812 06:19:24.847139 28858 log.cc:1079] T dfa425c1c7234bb6972a78bd6b5df7af P 514a191ac1ce4bdf9348e8ba6fa0a63c: Deleting log segment in path: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560090170-28680-0/minicluster-data/ts-0-root/wals/dfa425c1c7234bb6972a78bd6b5df7af/wal-000000030 (ops 143-146)
I20260812 06:19:24.847184 28858 log.cc:1079] T dfa425c1c7234bb6972a78bd6b5df7af P 514a191ac1ce4bdf9348e8ba6fa0a63c: Deleting log segment in path: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560090170-28680-0/minicluster-data/ts-0-root/wals/dfa425c1c7234bb6972a78bd6b5df7af/wal-000000031 (ops 147-151)
I20260812 06:19:24.847229 28858 log.cc:1079] T dfa425c1c7234bb6972a78bd6b5df7af P 514a191ac1ce4bdf9348e8ba6fa0a63c: Deleting log segment in path: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560090170-28680-0/minicluster-data/ts-0-root/wals/dfa425c1c7234bb6972a78bd6b5df7af/wal-000000032 (ops 152-156)
I20260812 06:19:24.847275 28858 log.cc:1079] T dfa425c1c7234bb6972a78bd6b5df7af P 514a191ac1ce4bdf9348e8ba6fa0a63c: Deleting log segment in path: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560090170-28680-0/minicluster-data/ts-0-root/wals/dfa425c1c7234bb6972a78bd6b5df7af/wal-000000033 (ops 157-160)
I20260812 06:19:24.847316 28858 log.cc:1079] T dfa425c1c7234bb6972a78bd6b5df7af P 514a191ac1ce4bdf9348e8ba6fa0a63c: Deleting log segment in path: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560090170-28680-0/minicluster-data/ts-0-root/wals/dfa425c1c7234bb6972a78bd6b5df7af/wal-000000034 (ops 161-165)
I20260812 06:19:24.847360 28858 log.cc:1079] T dfa425c1c7234bb6972a78bd6b5df7af P 514a191ac1ce4bdf9348e8ba6fa0a63c: Deleting log segment in path: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560090170-28680-0/minicluster-data/ts-0-root/wals/dfa425c1c7234bb6972a78bd6b5df7af/wal-000000035 (ops 166-170)
I20260812 06:19:24.847401 28858 log.cc:1079] T dfa425c1c7234bb6972a78bd6b5df7af P 514a191ac1ce4bdf9348e8ba6fa0a63c: Deleting log segment in path: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560090170-28680-0/minicluster-data/ts-0-root/wals/dfa425c1c7234bb6972a78bd6b5df7af/wal-000000036 (ops 171-174)
I20260812 06:19:24.847441 28858 log.cc:1079] T dfa425c1c7234bb6972a78bd6b5df7af P 514a191ac1ce4bdf9348e8ba6fa0a63c: Deleting log segment in path: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560090170-28680-0/minicluster-data/ts-0-root/wals/dfa425c1c7234bb6972a78bd6b5df7af/wal-000000037 (ops 175-179)
I20260812 06:19:24.847488 28858 log.cc:1079] T dfa425c1c7234bb6972a78bd6b5df7af P 514a191ac1ce4bdf9348e8ba6fa0a63c: Deleting log segment in path: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560090170-28680-0/minicluster-data/ts-0-root/wals/dfa425c1c7234bb6972a78bd6b5df7af/wal-000000038 (ops 180-184)
I20260812 06:19:24.868388 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: LogGCOp(dfa425c1c7234bb6972a78bd6b5df7af) complete. Timing: real 0.021s	user 0.003s	sys 0.015s Metrics: {}
I20260812 06:19:24.868834 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af): perf score=2.188937
I20260812 06:19:24.891697 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af) complete. Timing: real 0.023s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4451,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:24.892244 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling UndoDeltaBlockGCOp(dfa425c1c7234bb6972a78bd6b5df7af): 447 bytes on disk
I20260812 06:19:24.892707 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: UndoDeltaBlockGCOp(dfa425c1c7234bb6972a78bd6b5df7af) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4}
I20260812 06:19:24.893410 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af): perf score=2.188937
I20260812 06:19:24.903527 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3879,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:24.904055 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling MajorDeltaCompactionOp(dfa425c1c7234bb6972a78bd6b5df7af): perf score=1.000000
I20260812 06:19:25.147996 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: MajorDeltaCompactionOp(dfa425c1c7234bb6972a78bd6b5df7af) complete. Timing: real 0.244s	user 0.172s	sys 0.068s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979750,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":458,"lbm_read_time_us":16395,"lbm_reads_lt_1ms":774,"lbm_write_time_us":40832,"lbm_writes_lt_1ms":743,"mutex_wait_us":52,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":15232,"thread_start_us":87,"threads_started":1,"update_count":3500}
I20260812 06:19:25.148813 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af): perf score=18.063937
I20260812 06:19:25.201541 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: FlushDeltaMemStoresOp(dfa425c1c7234bb6972a78bd6b5df7af) complete. Timing: real 0.053s	user 0.033s	sys 0.019s Metrics: {"bytes_written":20512319,"delete_count":0,"lbm_write_time_us":23991,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:25.202049 28979 maintenance_manager.cc:419] P 514a191ac1ce4bdf9348e8ba6fa0a63c: Scheduling MajorDeltaCompactionOp(dfa425c1c7234bb6972a78bd6b5df7af): perf score=1.000000
I20260812 06:19:25.227443 28680 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.856s	user 1.722s	sys 0.180s
I20260812 06:19:25.296193 28680 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.068s	user 0.001s	sys 0.000s
I20260812 06:19:25.296833 28680 tablet_server.cc:179] TabletServer@127.28.2.1:0 shutting down...
I20260812 06:19:25.354156 28858 maintenance_manager.cc:643] P 514a191ac1ce4bdf9348e8ba6fa0a63c: MajorDeltaCompactionOp(dfa425c1c7234bb6972a78bd6b5df7af) complete. Timing: real 0.152s	user 0.099s	sys 0.052s Metrics: {"cfile_cache_miss":531,"cfile_cache_miss_bytes":24774575,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":314,"lbm_read_time_us":14044,"lbm_reads_lt_1ms":563,"lbm_write_time_us":24966,"lbm_writes_lt_1ms":543,"mutex_wait_us":49,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":18176,"update_count":2500}
I20260812 06:19:25.355006 28680 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:25.355381 28680 tablet_replica.cc:333] T dfa425c1c7234bb6972a78bd6b5df7af P 514a191ac1ce4bdf9348e8ba6fa0a63c: stopping tablet replica
I20260812 06:19:25.355612 28680 raft_consensus.cc:2243] T dfa425c1c7234bb6972a78bd6b5df7af P 514a191ac1ce4bdf9348e8ba6fa0a63c [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:25.355858 28680 raft_consensus.cc:2272] T dfa425c1c7234bb6972a78bd6b5df7af P 514a191ac1ce4bdf9348e8ba6fa0a63c [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:25.372800 28680 tablet_server.cc:196] TabletServer@127.28.2.1:0 shutdown complete.
I20260812 06:19:25.400456 28680 master.cc:562] Master@127.28.2.62:36423 shutting down...
I20260812 06:19:25.404282 28680 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 1eba75cd232e47dda548bfc848cc5b0e [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:25.404472 28680 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 1eba75cd232e47dda548bfc848cc5b0e [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:25.404570 28680 tablet_replica.cc:333] T 00000000000000000000000000000000 P 1eba75cd232e47dda548bfc848cc5b0e: stopping tablet replica
I20260812 06:19:25.416914 28680 master.cc:584] Master@127.28.2.62:36423 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5404 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:19:25.516724 28680 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.28.2.62:43645
I20260812 06:19:25.517170 28680 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:25.519495 29039 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:19:25.519615 29030 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:19:25.519629 29034 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:19:25.519799 28680 server_base.cc:1061] running on GCE node
I20260812 06:19:25.519989 28680 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:25.520045 28680 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:19:25.520071 28680 hybrid_clock.cc:648] HybridClock initialized: now 1786515565520070 us; error 0 us; skew 500 ppm
I20260812 06:19:25.521020 28680 webserver.cc:533] Webserver started at http://127.28.2.62:41443/ using document root <none> and password file <none>
I20260812 06:19:25.521209 28680 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:25.521281 28680 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:25.521409 28680 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:25.521837 28680 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560090170-28680-0/minicluster-data/master-0-root/instance:
uuid: "911a29536579403fa9ad4f9e1c43f421"
format_stamp: "Formatted at 2026-08-12 06:19:25 on dist-test-slave-j2vl"
I20260812 06:19:25.523401 28680 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:19:25.524324 29051 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:19:25.524574 28680 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:19:25.524667 28680 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560090170-28680-0/minicluster-data/master-0-root
uuid: "911a29536579403fa9ad4f9e1c43f421"
format_stamp: "Formatted at 2026-08-12 06:19:25 on dist-test-slave-j2vl"
I20260812 06:19:25.524756 28680 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560090170-28680-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560090170-28680-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560090170-28680-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:19:25.533118 28680 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:25.533528 28680 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:25.537421 28680 rpc_server.cc:307] RPC server started. Bound to: 127.28.2.62:43645
I20260812 06:19:25.537451 29149 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.28.2.62:43645 every 8 connection(s)
I20260812 06:19:25.538252 29151 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:19:25.541566 29151 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 911a29536579403fa9ad4f9e1c43f421: Bootstrap starting.
I20260812 06:19:25.542272 29151 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 911a29536579403fa9ad4f9e1c43f421: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:25.543179 29151 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 911a29536579403fa9ad4f9e1c43f421: No bootstrap required, opened a new log
I20260812 06:19:25.543509 29151 raft_consensus.cc:359] T 00000000000000000000000000000000 P 911a29536579403fa9ad4f9e1c43f421 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "911a29536579403fa9ad4f9e1c43f421" member_type: VOTER }
I20260812 06:19:25.543589 29151 raft_consensus.cc:385] T 00000000000000000000000000000000 P 911a29536579403fa9ad4f9e1c43f421 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:25.543612 29151 raft_consensus.cc:740] T 00000000000000000000000000000000 P 911a29536579403fa9ad4f9e1c43f421 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 911a29536579403fa9ad4f9e1c43f421, State: Initialized, Role: FOLLOWER
I20260812 06:19:25.543767 29151 consensus_queue.cc:260] T 00000000000000000000000000000000 P 911a29536579403fa9ad4f9e1c43f421 [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: "911a29536579403fa9ad4f9e1c43f421" member_type: VOTER }
I20260812 06:19:25.543870 29151 raft_consensus.cc:399] T 00000000000000000000000000000000 P 911a29536579403fa9ad4f9e1c43f421 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:25.543901 29151 raft_consensus.cc:493] T 00000000000000000000000000000000 P 911a29536579403fa9ad4f9e1c43f421 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:25.543937 29151 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 911a29536579403fa9ad4f9e1c43f421 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:25.544523 29151 raft_consensus.cc:515] T 00000000000000000000000000000000 P 911a29536579403fa9ad4f9e1c43f421 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "911a29536579403fa9ad4f9e1c43f421" member_type: VOTER }
I20260812 06:19:25.544627 29151 leader_election.cc:304] T 00000000000000000000000000000000 P 911a29536579403fa9ad4f9e1c43f421 [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: 911a29536579403fa9ad4f9e1c43f421; no voters: 
I20260812 06:19:25.544757 29151 leader_election.cc:290] T 00000000000000000000000000000000 P 911a29536579403fa9ad4f9e1c43f421 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:25.544878 29157 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 911a29536579403fa9ad4f9e1c43f421 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:25.545073 29157 raft_consensus.cc:697] T 00000000000000000000000000000000 P 911a29536579403fa9ad4f9e1c43f421 [term 1 LEADER]: Becoming Leader. State: Replica: 911a29536579403fa9ad4f9e1c43f421, State: Running, Role: LEADER
I20260812 06:19:25.545210 29157 consensus_queue.cc:237] T 00000000000000000000000000000000 P 911a29536579403fa9ad4f9e1c43f421 [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: "911a29536579403fa9ad4f9e1c43f421" member_type: VOTER }
I20260812 06:19:25.545223 29151 sys_catalog.cc:565] T 00000000000000000000000000000000 P 911a29536579403fa9ad4f9e1c43f421 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:25.545749 29159 sys_catalog.cc:455] T 00000000000000000000000000000000 P 911a29536579403fa9ad4f9e1c43f421 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "911a29536579403fa9ad4f9e1c43f421" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "911a29536579403fa9ad4f9e1c43f421" member_type: VOTER } }
I20260812 06:19:25.545773 29160 sys_catalog.cc:455] T 00000000000000000000000000000000 P 911a29536579403fa9ad4f9e1c43f421 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 911a29536579403fa9ad4f9e1c43f421. Latest consensus state: current_term: 1 leader_uuid: "911a29536579403fa9ad4f9e1c43f421" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "911a29536579403fa9ad4f9e1c43f421" member_type: VOTER } }
I20260812 06:19:25.545903 29159 sys_catalog.cc:458] T 00000000000000000000000000000000 P 911a29536579403fa9ad4f9e1c43f421 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:25.545957 29160 sys_catalog.cc:458] T 00000000000000000000000000000000 P 911a29536579403fa9ad4f9e1c43f421 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:25.546486 29165 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:25.547318 29165 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:25.547485 28680 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:25.549050 29165 catalog_manager.cc:1383] Generated new cluster ID: 5ccb2411305143fcb4e2597880a524f9
I20260812 06:19:25.549108 29165 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:25.559305 29165 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:25.559813 29165 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:25.567281 29165 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 911a29536579403fa9ad4f9e1c43f421: Generated new TSK 0
I20260812 06:19:25.567425 29165 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:25.579717 28680 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:25.581717 29182 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:19:25.581743 29184 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:19:25.581794 28680 server_base.cc:1061] running on GCE node
W20260812 06:19:25.581761 29186 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:19:25.582134 28680 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:25.582178 28680 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:19:25.582194 28680 hybrid_clock.cc:648] HybridClock initialized: now 1786515565582194 us; error 0 us; skew 500 ppm
I20260812 06:19:25.583024 28680 webserver.cc:533] Webserver started at http://127.28.2.1:43263/ using document root <none> and password file <none>
I20260812 06:19:25.583195 28680 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:25.583240 28680 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:25.583334 28680 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:25.583698 28680 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560090170-28680-0/minicluster-data/ts-0-root/instance:
uuid: "bf12e818f58d459b8f328b974eca534c"
format_stamp: "Formatted at 2026-08-12 06:19:25 on dist-test-slave-j2vl"
I20260812 06:19:25.585110 28680 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.001s
I20260812 06:19:25.586061 29192 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:19:25.586308 28680 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:25.586396 28680 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560090170-28680-0/minicluster-data/ts-0-root
uuid: "bf12e818f58d459b8f328b974eca534c"
format_stamp: "Formatted at 2026-08-12 06:19:25 on dist-test-slave-j2vl"
I20260812 06:19:25.586488 28680 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560090170-28680-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560090170-28680-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560090170-28680-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:19:25.603048 28680 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:25.603403 28680 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:25.603708 28680 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:25.604164 28680 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:25.604225 28680 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:25.604285 28680 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:25.604336 28680 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:25.609045 28680 rpc_server.cc:307] RPC server started. Bound to: 127.28.2.1:44653
I20260812 06:19:25.610929 29304 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.28.2.1:44653 every 8 connection(s)
I20260812 06:19:25.618757 29306 heartbeater.cc:344] Connected to a master server at 127.28.2.62:43645
I20260812 06:19:25.618892 29306 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:25.619136 29306 heartbeater.cc:507] Master 127.28.2.62:43645 requested a full tablet report, sending...
I20260812 06:19:25.619786 29081 ts_manager.cc:194] Registered new tserver with Master: bf12e818f58d459b8f328b974eca534c (127.28.2.1:44653)
I20260812 06:19:25.620035 28680 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.009950686s
I20260812 06:19:25.620605 29081 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:42186
I20260812 06:19:25.626984 29081 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:42200:
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:19:25.635516 29236 tablet_service.cc:1511] Processing CreateTablet for tablet 27bfafbb498d48749a63b4089a642948 (DEFAULT_TABLE table=heavy-update-compaction-test [id=60e0357f2a784359ac431324d048d686]), partition=
I20260812 06:19:25.635756 29236 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 27bfafbb498d48749a63b4089a642948. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:25.637600 29338 tablet_bootstrap.cc:492] T 27bfafbb498d48749a63b4089a642948 P bf12e818f58d459b8f328b974eca534c: Bootstrap starting.
I20260812 06:19:25.638393 29338 tablet_bootstrap.cc:654] T 27bfafbb498d48749a63b4089a642948 P bf12e818f58d459b8f328b974eca534c: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:25.639350 29338 tablet_bootstrap.cc:492] T 27bfafbb498d48749a63b4089a642948 P bf12e818f58d459b8f328b974eca534c: No bootstrap required, opened a new log
I20260812 06:19:25.639423 29338 ts_tablet_manager.cc:1403] T 27bfafbb498d48749a63b4089a642948 P bf12e818f58d459b8f328b974eca534c: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:19:25.639766 29338 raft_consensus.cc:359] T 27bfafbb498d48749a63b4089a642948 P bf12e818f58d459b8f328b974eca534c [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bf12e818f58d459b8f328b974eca534c" member_type: VOTER last_known_addr { host: "127.28.2.1" port: 44653 } }
I20260812 06:19:25.639853 29338 raft_consensus.cc:385] T 27bfafbb498d48749a63b4089a642948 P bf12e818f58d459b8f328b974eca534c [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:25.639874 29338 raft_consensus.cc:740] T 27bfafbb498d48749a63b4089a642948 P bf12e818f58d459b8f328b974eca534c [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: bf12e818f58d459b8f328b974eca534c, State: Initialized, Role: FOLLOWER
I20260812 06:19:25.640026 29338 consensus_queue.cc:260] T 27bfafbb498d48749a63b4089a642948 P bf12e818f58d459b8f328b974eca534c [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: "bf12e818f58d459b8f328b974eca534c" member_type: VOTER last_known_addr { host: "127.28.2.1" port: 44653 } }
I20260812 06:19:25.640116 29338 raft_consensus.cc:399] T 27bfafbb498d48749a63b4089a642948 P bf12e818f58d459b8f328b974eca534c [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:25.640141 29338 raft_consensus.cc:493] T 27bfafbb498d48749a63b4089a642948 P bf12e818f58d459b8f328b974eca534c [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:25.640177 29338 raft_consensus.cc:3060] T 27bfafbb498d48749a63b4089a642948 P bf12e818f58d459b8f328b974eca534c [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:25.640956 29338 raft_consensus.cc:515] T 27bfafbb498d48749a63b4089a642948 P bf12e818f58d459b8f328b974eca534c [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bf12e818f58d459b8f328b974eca534c" member_type: VOTER last_known_addr { host: "127.28.2.1" port: 44653 } }
I20260812 06:19:25.641132 29338 leader_election.cc:304] T 27bfafbb498d48749a63b4089a642948 P bf12e818f58d459b8f328b974eca534c [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: bf12e818f58d459b8f328b974eca534c; no voters: 
I20260812 06:19:25.641449 29338 leader_election.cc:290] T 27bfafbb498d48749a63b4089a642948 P bf12e818f58d459b8f328b974eca534c [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:25.641547 29344 raft_consensus.cc:2804] T 27bfafbb498d48749a63b4089a642948 P bf12e818f58d459b8f328b974eca534c [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:25.641804 29344 raft_consensus.cc:697] T 27bfafbb498d48749a63b4089a642948 P bf12e818f58d459b8f328b974eca534c [term 1 LEADER]: Becoming Leader. State: Replica: bf12e818f58d459b8f328b974eca534c, State: Running, Role: LEADER
I20260812 06:19:25.641842 29338 ts_tablet_manager.cc:1434] T 27bfafbb498d48749a63b4089a642948 P bf12e818f58d459b8f328b974eca534c: Time spent starting tablet: real 0.002s	user 0.000s	sys 0.003s
I20260812 06:19:25.641860 29306 heartbeater.cc:499] Master 127.28.2.62:43645 was elected leader, sending a full tablet report...
I20260812 06:19:25.641973 29344 consensus_queue.cc:237] T 27bfafbb498d48749a63b4089a642948 P bf12e818f58d459b8f328b974eca534c [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: "bf12e818f58d459b8f328b974eca534c" member_type: VOTER last_known_addr { host: "127.28.2.1" port: 44653 } }
I20260812 06:19:25.643183 29081 catalog_manager.cc:5719] T 27bfafbb498d48749a63b4089a642948 P bf12e818f58d459b8f328b974eca534c reported cstate change: term changed from 0 to 1, leader changed from <none> to bf12e818f58d459b8f328b974eca534c (127.28.2.1). New cstate: current_term: 1 leader_uuid: "bf12e818f58d459b8f328b974eca534c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bf12e818f58d459b8f328b974eca534c" member_type: VOTER last_known_addr { host: "127.28.2.1" port: 44653 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:25.700052 28680 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.053s	user 0.018s	sys 0.004s
I20260812 06:19:25.861953 29310 maintenance_manager.cc:419] P bf12e818f58d459b8f328b974eca534c: Scheduling FlushMRSOp(27bfafbb498d48749a63b4089a642948): perf score=23.023690
I20260812 06:19:26.025107 29200 maintenance_manager.cc:643] P bf12e818f58d459b8f328b974eca534c: FlushMRSOp(27bfafbb498d48749a63b4089a642948) complete. Timing: real 0.163s	user 0.099s	sys 0.060s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":58,"dirs.run_cpu_time_us":200,"dirs.run_wall_time_us":746,"drs_written":1,"lbm_read_time_us":41,"lbm_reads_lt_1ms":4,"lbm_write_time_us":41182,"lbm_writes_lt_1ms":857,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"update_count":1500}
I20260812 06:19:26.025961 29310 maintenance_manager.cc:419] P bf12e818f58d459b8f328b974eca534c: Scheduling LogGCOp(27bfafbb498d48749a63b4089a642948): free 20290830 bytes of WAL
I20260812 06:19:26.026245 29200 log_reader.cc:385] T 27bfafbb498d48749a63b4089a642948: removed 2 log segments from log reader
I20260812 06:19:26.026314 29200 log.cc:1079] T 27bfafbb498d48749a63b4089a642948 P bf12e818f58d459b8f328b974eca534c: Deleting log segment in path: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560090170-28680-0/minicluster-data/ts-0-root/wals/27bfafbb498d48749a63b4089a642948/wal-000000001 (ops 1-6)
I20260812 06:19:26.026355 29200 log.cc:1079] T 27bfafbb498d48749a63b4089a642948 P bf12e818f58d459b8f328b974eca534c: Deleting log segment in path: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560090170-28680-0/minicluster-data/ts-0-root/wals/27bfafbb498d48749a63b4089a642948/wal-000000002 (ops 7-10)
I20260812 06:19:26.031795 29200 maintenance_manager.cc:643] P bf12e818f58d459b8f328b974eca534c: LogGCOp(27bfafbb498d48749a63b4089a642948) complete. Timing: real 0.006s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:19:26.032196 29310 maintenance_manager.cc:419] P bf12e818f58d459b8f328b974eca534c: Scheduling FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948): perf score=2.188937
I20260812 06:19:26.050093 29200 maintenance_manager.cc:643] P bf12e818f58d459b8f328b974eca534c: FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948) complete. Timing: real 0.018s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6703,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:26.050684 29310 maintenance_manager.cc:419] P bf12e818f58d459b8f328b974eca534c: Scheduling UndoDeltaBlockGCOp(27bfafbb498d48749a63b4089a642948): 20513812 bytes on disk
I20260812 06:19:26.051182 29200 maintenance_manager.cc:643] P bf12e818f58d459b8f328b974eca534c: UndoDeltaBlockGCOp(27bfafbb498d48749a63b4089a642948) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":74,"lbm_reads_lt_1ms":4}
I20260812 06:19:26.051703 29310 maintenance_manager.cc:419] P bf12e818f58d459b8f328b974eca534c: Scheduling MajorDeltaCompactionOp(27bfafbb498d48749a63b4089a642948): perf score=1.000000
I20260812 06:19:26.213052 29200 maintenance_manager.cc:643] P bf12e818f58d459b8f328b974eca534c: MajorDeltaCompactionOp(27bfafbb498d48749a63b4089a642948) complete. Timing: real 0.161s	user 0.121s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":432,"lbm_read_time_us":12038,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25356,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4224,"thread_start_us":385,"threads_started":5,"update_count":2000}
I20260812 06:19:26.213681 29310 maintenance_manager.cc:419] P bf12e818f58d459b8f328b974eca534c: Scheduling FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948): perf score=10.126437
I20260812 06:19:26.250165 29200 maintenance_manager.cc:643] P bf12e818f58d459b8f328b974eca534c: FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948) complete. Timing: real 0.036s	user 0.012s	sys 0.024s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":12995,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:26.250952 29310 maintenance_manager.cc:419] P bf12e818f58d459b8f328b974eca534c: Scheduling FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948): perf score=2.188937
I20260812 06:19:26.266342 29200 maintenance_manager.cc:643] P bf12e818f58d459b8f328b974eca534c: FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948) complete. Timing: real 0.015s	user 0.001s	sys 0.012s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5190,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:26.266789 29310 maintenance_manager.cc:419] P bf12e818f58d459b8f328b974eca534c: Scheduling MajorDeltaCompactionOp(27bfafbb498d48749a63b4089a642948): perf score=1.000000
I20260812 06:19:26.398329 29200 maintenance_manager.cc:643] P bf12e818f58d459b8f328b974eca534c: MajorDeltaCompactionOp(27bfafbb498d48749a63b4089a642948) complete. Timing: real 0.131s	user 0.102s	sys 0.027s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":392,"lbm_read_time_us":8566,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23208,"lbm_writes_lt_1ms":443,"mutex_wait_us":2,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7040,"update_count":2000}
I20260812 06:19:26.399010 29310 maintenance_manager.cc:419] P bf12e818f58d459b8f328b974eca534c: Scheduling FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948): perf score=10.126437
I20260812 06:19:26.437641 29200 maintenance_manager.cc:643] P bf12e818f58d459b8f328b974eca534c: FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948) complete. Timing: real 0.038s	user 0.021s	sys 0.017s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17677,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:19:26.438179 29310 maintenance_manager.cc:419] P bf12e818f58d459b8f328b974eca534c: Scheduling FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948): perf score=2.188937
I20260812 06:19:26.455046 29200 maintenance_manager.cc:643] P bf12e818f58d459b8f328b974eca534c: FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948) complete. Timing: real 0.017s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5958,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:26.455652 29310 maintenance_manager.cc:419] P bf12e818f58d459b8f328b974eca534c: Scheduling MajorDeltaCompactionOp(27bfafbb498d48749a63b4089a642948): perf score=1.000000
I20260812 06:19:26.572605 29200 maintenance_manager.cc:643] P bf12e818f58d459b8f328b974eca534c: MajorDeltaCompactionOp(27bfafbb498d48749a63b4089a642948) complete. Timing: real 0.117s	user 0.093s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":438,"lbm_read_time_us":9448,"lbm_reads_lt_1ms":468,"lbm_write_time_us":21615,"lbm_writes_lt_1ms":443,"mutex_wait_us":78,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7424,"update_count":2000}
I20260812 06:19:26.573439 29310 maintenance_manager.cc:419] P bf12e818f58d459b8f328b974eca534c: Scheduling FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948): perf score=10.126437
I20260812 06:19:26.613477 29200 maintenance_manager.cc:643] P bf12e818f58d459b8f328b974eca534c: FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948) complete. Timing: real 0.040s	user 0.027s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17296,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:26.613961 29310 maintenance_manager.cc:419] P bf12e818f58d459b8f328b974eca534c: Scheduling FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948): perf score=2.188937
I20260812 06:19:26.625494 29200 maintenance_manager.cc:643] P bf12e818f58d459b8f328b974eca534c: FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948) complete. Timing: real 0.011s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3994,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:26.626034 29310 maintenance_manager.cc:419] P bf12e818f58d459b8f328b974eca534c: Scheduling MajorDeltaCompactionOp(27bfafbb498d48749a63b4089a642948): perf score=1.000000
I20260812 06:19:26.756291 29200 maintenance_manager.cc:643] P bf12e818f58d459b8f328b974eca534c: MajorDeltaCompactionOp(27bfafbb498d48749a63b4089a642948) complete. Timing: real 0.130s	user 0.102s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":894,"lbm_read_time_us":8099,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26705,"lbm_writes_lt_1ms":443,"mutex_wait_us":63,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11648,"update_count":2000}
I20260812 06:19:26.756748 29310 maintenance_manager.cc:419] P bf12e818f58d459b8f328b974eca534c: Scheduling FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948): perf score=10.126437
I20260812 06:19:26.806300 29200 maintenance_manager.cc:643] P bf12e818f58d459b8f328b974eca534c: FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948) complete. Timing: real 0.049s	user 0.034s	sys 0.011s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15273,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:26.806901 29310 maintenance_manager.cc:419] P bf12e818f58d459b8f328b974eca534c: Scheduling FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948): perf score=2.188937
I20260812 06:19:26.818226 29200 maintenance_manager.cc:643] P bf12e818f58d459b8f328b974eca534c: FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4420,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:26.818678 29310 maintenance_manager.cc:419] P bf12e818f58d459b8f328b974eca534c: Scheduling MajorDeltaCompactionOp(27bfafbb498d48749a63b4089a642948): perf score=1.000000
I20260812 06:19:26.971675 29200 maintenance_manager.cc:643] P bf12e818f58d459b8f328b974eca534c: MajorDeltaCompactionOp(27bfafbb498d48749a63b4089a642948) complete. Timing: real 0.153s	user 0.098s	sys 0.054s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713271,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":932,"lbm_read_time_us":11053,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26081,"lbm_writes_lt_1ms":443,"mutex_wait_us":296,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":2000}
I20260812 06:19:26.972231 29310 maintenance_manager.cc:419] P bf12e818f58d459b8f328b974eca534c: Scheduling FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948): perf score=10.126437
I20260812 06:19:27.017947 29200 maintenance_manager.cc:643] P bf12e818f58d459b8f328b974eca534c: FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948) complete. Timing: real 0.046s	user 0.021s	sys 0.019s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":17293,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:27.018456 29310 maintenance_manager.cc:419] P bf12e818f58d459b8f328b974eca534c: Scheduling FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948): perf score=2.188937
I20260812 06:19:27.029277 29200 maintenance_manager.cc:643] P bf12e818f58d459b8f328b974eca534c: FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4059,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:27.029907 29310 maintenance_manager.cc:419] P bf12e818f58d459b8f328b974eca534c: Scheduling MajorDeltaCompactionOp(27bfafbb498d48749a63b4089a642948): perf score=1.000000
I20260812 06:19:27.156615 29200 maintenance_manager.cc:643] P bf12e818f58d459b8f328b974eca534c: MajorDeltaCompactionOp(27bfafbb498d48749a63b4089a642948) complete. Timing: real 0.126s	user 0.118s	sys 0.008s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713274,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":254,"lbm_read_time_us":9603,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21873,"lbm_writes_lt_1ms":443,"mutex_wait_us":28,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":15616,"update_count":2000}
I20260812 06:19:27.157447 29310 maintenance_manager.cc:419] P bf12e818f58d459b8f328b974eca534c: Scheduling FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948): perf score=10.126437
I20260812 06:19:27.200104 29200 maintenance_manager.cc:643] P bf12e818f58d459b8f328b974eca534c: FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948) complete. Timing: real 0.042s	user 0.017s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14239,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:27.200603 29310 maintenance_manager.cc:419] P bf12e818f58d459b8f328b974eca534c: Scheduling FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948): perf score=2.188937
I20260812 06:19:27.211177 29200 maintenance_manager.cc:643] P bf12e818f58d459b8f328b974eca534c: FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4067,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:27.211900 29310 maintenance_manager.cc:419] P bf12e818f58d459b8f328b974eca534c: Scheduling FlushMRSOp(27bfafbb498d48749a63b4089a642948): perf score=1.000000
I20260812 06:19:27.242992 29200 maintenance_manager.cc:643] P bf12e818f58d459b8f328b974eca534c: FlushMRSOp(27bfafbb498d48749a63b4089a642948) complete. Timing: real 0.031s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":67,"dirs.run_cpu_time_us":273,"dirs.run_wall_time_us":1275,"drs_written":1,"lbm_read_time_us":35,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1699,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:27.243603 29310 maintenance_manager.cc:419] P bf12e818f58d459b8f328b974eca534c: Scheduling LogGCOp(27bfafbb498d48749a63b4089a642948): free 121006371 bytes of WAL
I20260812 06:19:27.243841 29200 log_reader.cc:385] T 27bfafbb498d48749a63b4089a642948: removed 12 log segments from log reader
I20260812 06:19:27.243889 29200 log.cc:1079] T 27bfafbb498d48749a63b4089a642948 P bf12e818f58d459b8f328b974eca534c: Deleting log segment in path: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560090170-28680-0/minicluster-data/ts-0-root/wals/27bfafbb498d48749a63b4089a642948/wal-000000003 (ops 11-15)
I20260812 06:19:27.243917 29200 log.cc:1079] T 27bfafbb498d48749a63b4089a642948 P bf12e818f58d459b8f328b974eca534c: Deleting log segment in path: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560090170-28680-0/minicluster-data/ts-0-root/wals/27bfafbb498d48749a63b4089a642948/wal-000000004 (ops 16-20)
I20260812 06:19:27.243989 29200 log.cc:1079] T 27bfafbb498d48749a63b4089a642948 P bf12e818f58d459b8f328b974eca534c: Deleting log segment in path: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560090170-28680-0/minicluster-data/ts-0-root/wals/27bfafbb498d48749a63b4089a642948/wal-000000005 (ops 21-24)
I20260812 06:19:27.244035 29200 log.cc:1079] T 27bfafbb498d48749a63b4089a642948 P bf12e818f58d459b8f328b974eca534c: Deleting log segment in path: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560090170-28680-0/minicluster-data/ts-0-root/wals/27bfafbb498d48749a63b4089a642948/wal-000000006 (ops 25-29)
I20260812 06:19:27.244072 29200 log.cc:1079] T 27bfafbb498d48749a63b4089a642948 P bf12e818f58d459b8f328b974eca534c: Deleting log segment in path: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560090170-28680-0/minicluster-data/ts-0-root/wals/27bfafbb498d48749a63b4089a642948/wal-000000007 (ops 30-34)
I20260812 06:19:27.244133 29200 log.cc:1079] T 27bfafbb498d48749a63b4089a642948 P bf12e818f58d459b8f328b974eca534c: Deleting log segment in path: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560090170-28680-0/minicluster-data/ts-0-root/wals/27bfafbb498d48749a63b4089a642948/wal-000000008 (ops 35-39)
I20260812 06:19:27.244181 29200 log.cc:1079] T 27bfafbb498d48749a63b4089a642948 P bf12e818f58d459b8f328b974eca534c: Deleting log segment in path: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560090170-28680-0/minicluster-data/ts-0-root/wals/27bfafbb498d48749a63b4089a642948/wal-000000009 (ops 40-44)
I20260812 06:19:27.244218 29200 log.cc:1079] T 27bfafbb498d48749a63b4089a642948 P bf12e818f58d459b8f328b974eca534c: Deleting log segment in path: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560090170-28680-0/minicluster-data/ts-0-root/wals/27bfafbb498d48749a63b4089a642948/wal-000000010 (ops 45-49)
I20260812 06:19:27.244269 29200 log.cc:1079] T 27bfafbb498d48749a63b4089a642948 P bf12e818f58d459b8f328b974eca534c: Deleting log segment in path: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560090170-28680-0/minicluster-data/ts-0-root/wals/27bfafbb498d48749a63b4089a642948/wal-000000011 (ops 50-54)
I20260812 06:19:27.244305 29200 log.cc:1079] T 27bfafbb498d48749a63b4089a642948 P bf12e818f58d459b8f328b974eca534c: Deleting log segment in path: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560090170-28680-0/minicluster-data/ts-0-root/wals/27bfafbb498d48749a63b4089a642948/wal-000000012 (ops 55-59)
I20260812 06:19:27.244344 29200 log.cc:1079] T 27bfafbb498d48749a63b4089a642948 P bf12e818f58d459b8f328b974eca534c: Deleting log segment in path: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560090170-28680-0/minicluster-data/ts-0-root/wals/27bfafbb498d48749a63b4089a642948/wal-000000013 (ops 60-64)
I20260812 06:19:27.244385 29200 log.cc:1079] T 27bfafbb498d48749a63b4089a642948 P bf12e818f58d459b8f328b974eca534c: Deleting log segment in path: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560090170-28680-0/minicluster-data/ts-0-root/wals/27bfafbb498d48749a63b4089a642948/wal-000000014 (ops 65-69)
I20260812 06:19:27.271005 29200 maintenance_manager.cc:643] P bf12e818f58d459b8f328b974eca534c: LogGCOp(27bfafbb498d48749a63b4089a642948) complete. Timing: real 0.027s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:19:27.271387 29310 maintenance_manager.cc:419] P bf12e818f58d459b8f328b974eca534c: Scheduling FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948): perf score=3.181125
I20260812 06:19:27.290664 29200 maintenance_manager.cc:643] P bf12e818f58d459b8f328b974eca534c: FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948) complete. Timing: real 0.019s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4512899,"delete_count":0,"lbm_write_time_us":7259,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:27.291122 29310 maintenance_manager.cc:419] P bf12e818f58d459b8f328b974eca534c: Scheduling FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948): perf score=2.188937
I20260812 06:19:27.300148 29200 maintenance_manager.cc:643] P bf12e818f58d459b8f328b974eca534c: FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948) complete. Timing: real 0.009s	user 0.004s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3506,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:27.300647 29310 maintenance_manager.cc:419] P bf12e818f58d459b8f328b974eca534c: Scheduling UndoDeltaBlockGCOp(27bfafbb498d48749a63b4089a642948): 447 bytes on disk
I20260812 06:19:27.301077 29200 maintenance_manager.cc:643] P bf12e818f58d459b8f328b974eca534c: UndoDeltaBlockGCOp(27bfafbb498d48749a63b4089a642948) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4}
I20260812 06:19:27.301755 29310 maintenance_manager.cc:419] P bf12e818f58d459b8f328b974eca534c: Scheduling MajorDeltaCompactionOp(27bfafbb498d48749a63b4089a642948): perf score=1.000000
I20260812 06:19:27.474983 29200 maintenance_manager.cc:643] P bf12e818f58d459b8f328b974eca534c: MajorDeltaCompactionOp(27bfafbb498d48749a63b4089a642948) complete. Timing: real 0.173s	user 0.146s	sys 0.025s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918320,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":695,"lbm_read_time_us":12155,"lbm_reads_lt_1ms":674,"lbm_write_time_us":33135,"lbm_writes_lt_1ms":643,"mutex_wait_us":85,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":10112,"thread_start_us":90,"threads_started":1,"update_count":3000}
I20260812 06:19:27.475693 29310 maintenance_manager.cc:419] P bf12e818f58d459b8f328b974eca534c: Scheduling FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948): perf score=14.095187
I20260812 06:19:27.524811 29200 maintenance_manager.cc:643] P bf12e818f58d459b8f328b974eca534c: FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948) complete. Timing: real 0.049s	user 0.020s	sys 0.020s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":18932,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:27.525430 29310 maintenance_manager.cc:419] P bf12e818f58d459b8f328b974eca534c: Scheduling FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948): perf score=2.188937
I20260812 06:19:27.540570 29200 maintenance_manager.cc:643] P bf12e818f58d459b8f328b974eca534c: FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5662,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:27.541105 29310 maintenance_manager.cc:419] P bf12e818f58d459b8f328b974eca534c: Scheduling MajorDeltaCompactionOp(27bfafbb498d48749a63b4089a642948): perf score=1.000000
I20260812 06:19:27.701436 29200 maintenance_manager.cc:643] P bf12e818f58d459b8f328b974eca534c: MajorDeltaCompactionOp(27bfafbb498d48749a63b4089a642948) complete. Timing: real 0.160s	user 0.126s	sys 0.023s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":807,"lbm_read_time_us":10952,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28084,"lbm_writes_lt_1ms":543,"mutex_wait_us":52,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11648,"update_count":2500}
I20260812 06:19:27.702133 29310 maintenance_manager.cc:419] P bf12e818f58d459b8f328b974eca534c: Scheduling FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948): perf score=14.095187
I20260812 06:19:27.757515 29200 maintenance_manager.cc:643] P bf12e818f58d459b8f328b974eca534c: FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948) complete. Timing: real 0.055s	user 0.037s	sys 0.013s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22068,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:27.757992 29310 maintenance_manager.cc:419] P bf12e818f58d459b8f328b974eca534c: Scheduling FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948): perf score=2.188937
I20260812 06:19:27.768585 29200 maintenance_manager.cc:643] P bf12e818f58d459b8f328b974eca534c: FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3978,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:27.769045 29310 maintenance_manager.cc:419] P bf12e818f58d459b8f328b974eca534c: Scheduling MajorDeltaCompactionOp(27bfafbb498d48749a63b4089a642948): perf score=1.000000
I20260812 06:19:27.919545 29200 maintenance_manager.cc:643] P bf12e818f58d459b8f328b974eca534c: MajorDeltaCompactionOp(27bfafbb498d48749a63b4089a642948) complete. Timing: real 0.150s	user 0.115s	sys 0.028s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":227,"lbm_read_time_us":10560,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27450,"lbm_writes_lt_1ms":543,"mutex_wait_us":39,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4096,"update_count":2500}
I20260812 06:19:27.920239 29310 maintenance_manager.cc:419] P bf12e818f58d459b8f328b974eca534c: Scheduling FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948): perf score=14.095187
I20260812 06:19:27.974072 29200 maintenance_manager.cc:643] P bf12e818f58d459b8f328b974eca534c: FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948) complete. Timing: real 0.054s	user 0.039s	sys 0.007s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20641,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:27.974586 29310 maintenance_manager.cc:419] P bf12e818f58d459b8f328b974eca534c: Scheduling FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948): perf score=2.188937
I20260812 06:19:27.986163 29200 maintenance_manager.cc:643] P bf12e818f58d459b8f328b974eca534c: FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4253,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:27.986635 29310 maintenance_manager.cc:419] P bf12e818f58d459b8f328b974eca534c: Scheduling MajorDeltaCompactionOp(27bfafbb498d48749a63b4089a642948): perf score=1.000000
I20260812 06:19:28.143922 29200 maintenance_manager.cc:643] P bf12e818f58d459b8f328b974eca534c: MajorDeltaCompactionOp(27bfafbb498d48749a63b4089a642948) complete. Timing: real 0.157s	user 0.120s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":783,"lbm_read_time_us":10834,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30752,"lbm_writes_lt_1ms":543,"mutex_wait_us":71,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":48128,"update_count":2500}
I20260812 06:19:28.144752 29310 maintenance_manager.cc:419] P bf12e818f58d459b8f328b974eca534c: Scheduling FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948): perf score=12.110812
I20260812 06:19:28.189409 29200 maintenance_manager.cc:643] P bf12e818f58d459b8f328b974eca534c: FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948) complete. Timing: real 0.044s	user 0.037s	sys 0.003s Metrics: {"bytes_written":13784349,"delete_count":0,"lbm_write_time_us":17783,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":338,"reinsert_count":0,"update_count":1680}
I20260812 06:19:28.189924 29310 maintenance_manager.cc:419] P bf12e818f58d459b8f328b974eca534c: Scheduling FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948): perf score=1.196750
I20260812 06:19:28.204873 29200 maintenance_manager.cc:643] P bf12e818f58d459b8f328b974eca534c: FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948) complete. Timing: real 0.015s	user 0.002s	sys 0.004s Metrics: {"bytes_written":3036009,"delete_count":0,"lbm_write_time_us":2846,"lbm_writes_lt_1ms":77,"reinsert_count":0,"update_count":370}
I20260812 06:19:28.205415 29310 maintenance_manager.cc:419] P bf12e818f58d459b8f328b974eca534c: Scheduling FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948): perf score=2.188937
I20260812 06:19:28.215005 29200 maintenance_manager.cc:643] P bf12e818f58d459b8f328b974eca534c: FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948) complete. Timing: real 0.009s	user 0.003s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3350,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:28.215435 29310 maintenance_manager.cc:419] P bf12e818f58d459b8f328b974eca534c: Scheduling MajorDeltaCompactionOp(27bfafbb498d48749a63b4089a642948): perf score=1.000000
I20260812 06:19:28.391428 29200 maintenance_manager.cc:643] P bf12e818f58d459b8f328b974eca534c: MajorDeltaCompactionOp(27bfafbb498d48749a63b4089a642948) complete. Timing: real 0.176s	user 0.119s	sys 0.052s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815758,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":535,"lbm_read_time_us":12019,"lbm_reads_lt_1ms":573,"lbm_write_time_us":31242,"lbm_writes_lt_1ms":543,"mutex_wait_us":270,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4864,"update_count":2500}
I20260812 06:19:28.392050 29310 maintenance_manager.cc:419] P bf12e818f58d459b8f328b974eca534c: Scheduling FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948): perf score=14.095187
I20260812 06:19:28.454746 29200 maintenance_manager.cc:643] P bf12e818f58d459b8f328b974eca534c: FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948) complete. Timing: real 0.063s	user 0.033s	sys 0.015s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21945,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:28.455353 29310 maintenance_manager.cc:419] P bf12e818f58d459b8f328b974eca534c: Scheduling FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948): perf score=2.188937
I20260812 06:19:28.468699 29200 maintenance_manager.cc:643] P bf12e818f58d459b8f328b974eca534c: FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4897,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:28.469314 29310 maintenance_manager.cc:419] P bf12e818f58d459b8f328b974eca534c: Scheduling MajorDeltaCompactionOp(27bfafbb498d48749a63b4089a642948): perf score=1.000000
I20260812 06:19:28.632633 29200 maintenance_manager.cc:643] P bf12e818f58d459b8f328b974eca534c: MajorDeltaCompactionOp(27bfafbb498d48749a63b4089a642948) complete. Timing: real 0.163s	user 0.094s	sys 0.065s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":621,"lbm_read_time_us":11153,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26931,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10752,"update_count":2500}
I20260812 06:19:28.633445 29310 maintenance_manager.cc:419] P bf12e818f58d459b8f328b974eca534c: Scheduling FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948): perf score=14.095187
I20260812 06:19:28.689864 29200 maintenance_manager.cc:643] P bf12e818f58d459b8f328b974eca534c: FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948) complete. Timing: real 0.056s	user 0.034s	sys 0.015s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":17531,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:28.690430 29310 maintenance_manager.cc:419] P bf12e818f58d459b8f328b974eca534c: Scheduling FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948): perf score=2.188937
I20260812 06:19:28.700848 29200 maintenance_manager.cc:643] P bf12e818f58d459b8f328b974eca534c: FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4055,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:28.701292 29310 maintenance_manager.cc:419] P bf12e818f58d459b8f328b974eca534c: Scheduling FlushMRSOp(27bfafbb498d48749a63b4089a642948): perf score=1.000000
I20260812 06:19:28.745708 29200 maintenance_manager.cc:643] P bf12e818f58d459b8f328b974eca534c: FlushMRSOp(27bfafbb498d48749a63b4089a642948) complete. Timing: real 0.044s	user 0.027s	sys 0.009s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":49,"dirs.run_cpu_time_us":172,"dirs.run_wall_time_us":1251,"drs_written":1,"lbm_read_time_us":112,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2145,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:19:28.746445 29310 maintenance_manager.cc:419] P bf12e818f58d459b8f328b974eca534c: Scheduling LogGCOp(27bfafbb498d48749a63b4089a642948): free 133024444 bytes of WAL
I20260812 06:19:28.746699 29200 log_reader.cc:385] T 27bfafbb498d48749a63b4089a642948: removed 13 log segments from log reader
I20260812 06:19:28.746745 29200 log.cc:1079] T 27bfafbb498d48749a63b4089a642948 P bf12e818f58d459b8f328b974eca534c: Deleting log segment in path: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560090170-28680-0/minicluster-data/ts-0-root/wals/27bfafbb498d48749a63b4089a642948/wal-000000015 (ops 70-74)
I20260812 06:19:28.746797 29200 log.cc:1079] T 27bfafbb498d48749a63b4089a642948 P bf12e818f58d459b8f328b974eca534c: Deleting log segment in path: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560090170-28680-0/minicluster-data/ts-0-root/wals/27bfafbb498d48749a63b4089a642948/wal-000000016 (ops 75-79)
I20260812 06:19:28.746889 29200 log.cc:1079] T 27bfafbb498d48749a63b4089a642948 P bf12e818f58d459b8f328b974eca534c: Deleting log segment in path: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560090170-28680-0/minicluster-data/ts-0-root/wals/27bfafbb498d48749a63b4089a642948/wal-000000017 (ops 80-84)
I20260812 06:19:28.746920 29200 log.cc:1079] T 27bfafbb498d48749a63b4089a642948 P bf12e818f58d459b8f328b974eca534c: Deleting log segment in path: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560090170-28680-0/minicluster-data/ts-0-root/wals/27bfafbb498d48749a63b4089a642948/wal-000000018 (ops 85-89)
I20260812 06:19:28.746938 29200 log.cc:1079] T 27bfafbb498d48749a63b4089a642948 P bf12e818f58d459b8f328b974eca534c: Deleting log segment in path: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560090170-28680-0/minicluster-data/ts-0-root/wals/27bfafbb498d48749a63b4089a642948/wal-000000019 (ops 90-94)
I20260812 06:19:28.746996 29200 log.cc:1079] T 27bfafbb498d48749a63b4089a642948 P bf12e818f58d459b8f328b974eca534c: Deleting log segment in path: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560090170-28680-0/minicluster-data/ts-0-root/wals/27bfafbb498d48749a63b4089a642948/wal-000000020 (ops 95-99)
I20260812 06:19:28.747038 29200 log.cc:1079] T 27bfafbb498d48749a63b4089a642948 P bf12e818f58d459b8f328b974eca534c: Deleting log segment in path: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560090170-28680-0/minicluster-data/ts-0-root/wals/27bfafbb498d48749a63b4089a642948/wal-000000021 (ops 100-104)
I20260812 06:19:28.747077 29200 log.cc:1079] T 27bfafbb498d48749a63b4089a642948 P bf12e818f58d459b8f328b974eca534c: Deleting log segment in path: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560090170-28680-0/minicluster-data/ts-0-root/wals/27bfafbb498d48749a63b4089a642948/wal-000000022 (ops 105-109)
I20260812 06:19:28.747121 29200 log.cc:1079] T 27bfafbb498d48749a63b4089a642948 P bf12e818f58d459b8f328b974eca534c: Deleting log segment in path: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560090170-28680-0/minicluster-data/ts-0-root/wals/27bfafbb498d48749a63b4089a642948/wal-000000023 (ops 110-114)
I20260812 06:19:28.747160 29200 log.cc:1079] T 27bfafbb498d48749a63b4089a642948 P bf12e818f58d459b8f328b974eca534c: Deleting log segment in path: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560090170-28680-0/minicluster-data/ts-0-root/wals/27bfafbb498d48749a63b4089a642948/wal-000000024 (ops 115-119)
I20260812 06:19:28.747200 29200 log.cc:1079] T 27bfafbb498d48749a63b4089a642948 P bf12e818f58d459b8f328b974eca534c: Deleting log segment in path: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560090170-28680-0/minicluster-data/ts-0-root/wals/27bfafbb498d48749a63b4089a642948/wal-000000025 (ops 120-124)
I20260812 06:19:28.747239 29200 log.cc:1079] T 27bfafbb498d48749a63b4089a642948 P bf12e818f58d459b8f328b974eca534c: Deleting log segment in path: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560090170-28680-0/minicluster-data/ts-0-root/wals/27bfafbb498d48749a63b4089a642948/wal-000000026 (ops 125-128)
I20260812 06:19:28.747278 29200 log.cc:1079] T 27bfafbb498d48749a63b4089a642948 P bf12e818f58d459b8f328b974eca534c: Deleting log segment in path: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560090170-28680-0/minicluster-data/ts-0-root/wals/27bfafbb498d48749a63b4089a642948/wal-000000027 (ops 129-133)
I20260812 06:19:28.773151 29200 maintenance_manager.cc:643] P bf12e818f58d459b8f328b974eca534c: LogGCOp(27bfafbb498d48749a63b4089a642948) complete. Timing: real 0.027s	user 0.004s	sys 0.019s Metrics: {}
I20260812 06:19:28.773536 29310 maintenance_manager.cc:419] P bf12e818f58d459b8f328b974eca534c: Scheduling FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948): perf score=3.181125
I20260812 06:19:28.787611 29200 maintenance_manager.cc:643] P bf12e818f58d459b8f328b974eca534c: FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948) complete. Timing: real 0.014s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4314,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:28.788055 29310 maintenance_manager.cc:419] P bf12e818f58d459b8f328b974eca534c: Scheduling UndoDeltaBlockGCOp(27bfafbb498d48749a63b4089a642948): 492 bytes on disk
I20260812 06:19:28.788441 29200 maintenance_manager.cc:643] P bf12e818f58d459b8f328b974eca534c: UndoDeltaBlockGCOp(27bfafbb498d48749a63b4089a642948) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4}
I20260812 06:19:28.788906 29310 maintenance_manager.cc:419] P bf12e818f58d459b8f328b974eca534c: Scheduling FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948): perf score=2.188937
I20260812 06:19:28.798362 29200 maintenance_manager.cc:643] P bf12e818f58d459b8f328b974eca534c: FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948) complete. Timing: real 0.009s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3606,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:28.798776 29310 maintenance_manager.cc:419] P bf12e818f58d459b8f328b974eca534c: Scheduling MajorDeltaCompactionOp(27bfafbb498d48749a63b4089a642948): perf score=1.000000
I20260812 06:19:29.024642 29200 maintenance_manager.cc:643] P bf12e818f58d459b8f328b974eca534c: MajorDeltaCompactionOp(27bfafbb498d48749a63b4089a642948) complete. Timing: real 0.226s	user 0.145s	sys 0.076s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020735,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":322,"lbm_read_time_us":16468,"lbm_reads_lt_1ms":774,"lbm_write_time_us":40176,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":71,"threads_started":1,"update_count":3500}
I20260812 06:19:29.025893 29310 maintenance_manager.cc:419] P bf12e818f58d459b8f328b974eca534c: Scheduling FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948): perf score=18.063937
I20260812 06:19:29.091507 29200 maintenance_manager.cc:643] P bf12e818f58d459b8f328b974eca534c: FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948) complete. Timing: real 0.065s	user 0.054s	sys 0.008s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":28954,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:29.092018 29310 maintenance_manager.cc:419] P bf12e818f58d459b8f328b974eca534c: Scheduling FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948): perf score=2.188937
I20260812 06:19:29.102869 29200 maintenance_manager.cc:643] P bf12e818f58d459b8f328b974eca534c: FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948) complete. Timing: real 0.011s	user 0.008s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3799,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:29.103319 29310 maintenance_manager.cc:419] P bf12e818f58d459b8f328b974eca534c: Scheduling MajorDeltaCompactionOp(27bfafbb498d48749a63b4089a642948): perf score=1.000000
I20260812 06:19:29.266485 29200 maintenance_manager.cc:643] P bf12e818f58d459b8f328b974eca534c: MajorDeltaCompactionOp(27bfafbb498d48749a63b4089a642948) complete. Timing: real 0.163s	user 0.110s	sys 0.053s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918099,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":242,"lbm_read_time_us":10402,"lbm_reads_lt_1ms":672,"lbm_write_time_us":35486,"lbm_writes_lt_1ms":643,"mutex_wait_us":41,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1536,"update_count":3000}
I20260812 06:19:29.267153 29310 maintenance_manager.cc:419] P bf12e818f58d459b8f328b974eca534c: Scheduling FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948): perf score=14.095187
I20260812 06:19:29.315130 29200 maintenance_manager.cc:643] P bf12e818f58d459b8f328b974eca534c: FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948) complete. Timing: real 0.048s	user 0.026s	sys 0.020s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":21081,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:29.315819 29310 maintenance_manager.cc:419] P bf12e818f58d459b8f328b974eca534c: Scheduling FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948): perf score=2.188937
I20260812 06:19:29.329988 29200 maintenance_manager.cc:643] P bf12e818f58d459b8f328b974eca534c: FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948) complete. Timing: real 0.014s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5221,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:29.330439 29310 maintenance_manager.cc:419] P bf12e818f58d459b8f328b974eca534c: Scheduling MajorDeltaCompactionOp(27bfafbb498d48749a63b4089a642948): perf score=1.000000
I20260812 06:19:29.480536 29200 maintenance_manager.cc:643] P bf12e818f58d459b8f328b974eca534c: MajorDeltaCompactionOp(27bfafbb498d48749a63b4089a642948) complete. Timing: real 0.150s	user 0.106s	sys 0.043s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":683,"lbm_read_time_us":10259,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26685,"lbm_writes_lt_1ms":543,"mutex_wait_us":29,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":77056,"update_count":2500}
I20260812 06:19:29.483987 29310 maintenance_manager.cc:419] P bf12e818f58d459b8f328b974eca534c: Scheduling FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948): perf score=14.095187
I20260812 06:19:29.543941 29200 maintenance_manager.cc:643] P bf12e818f58d459b8f328b974eca534c: FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948) complete. Timing: real 0.060s	user 0.021s	sys 0.025s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21691,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:29.544374 29310 maintenance_manager.cc:419] P bf12e818f58d459b8f328b974eca534c: Scheduling FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948): perf score=2.188937
I20260812 06:19:29.554932 29200 maintenance_manager.cc:643] P bf12e818f58d459b8f328b974eca534c: FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3927,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:29.555502 29310 maintenance_manager.cc:419] P bf12e818f58d459b8f328b974eca534c: Scheduling MajorDeltaCompactionOp(27bfafbb498d48749a63b4089a642948): perf score=1.000000
I20260812 06:19:29.734913 29200 maintenance_manager.cc:643] P bf12e818f58d459b8f328b974eca534c: MajorDeltaCompactionOp(27bfafbb498d48749a63b4089a642948) complete. Timing: real 0.179s	user 0.130s	sys 0.039s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1124,"lbm_read_time_us":12411,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29428,"lbm_writes_lt_1ms":543,"mutex_wait_us":289,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":19968,"update_count":2500}
I20260812 06:19:29.735553 29310 maintenance_manager.cc:419] P bf12e818f58d459b8f328b974eca534c: Scheduling FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948): perf score=14.095187
I20260812 06:19:29.797772 29200 maintenance_manager.cc:643] P bf12e818f58d459b8f328b974eca534c: FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948) complete. Timing: real 0.062s	user 0.029s	sys 0.026s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20111,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:29.798252 29310 maintenance_manager.cc:419] P bf12e818f58d459b8f328b974eca534c: Scheduling FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948): perf score=2.188937
I20260812 06:19:29.808437 29200 maintenance_manager.cc:643] P bf12e818f58d459b8f328b974eca534c: FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3954,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:29.808868 29310 maintenance_manager.cc:419] P bf12e818f58d459b8f328b974eca534c: Scheduling MajorDeltaCompactionOp(27bfafbb498d48749a63b4089a642948): perf score=1.000000
I20260812 06:19:29.982823 29200 maintenance_manager.cc:643] P bf12e818f58d459b8f328b974eca534c: MajorDeltaCompactionOp(27bfafbb498d48749a63b4089a642948) complete. Timing: real 0.174s	user 0.126s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":58,"lbm_read_time_us":12982,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28851,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12032,"update_count":2500}
I20260812 06:19:29.984498 29310 maintenance_manager.cc:419] P bf12e818f58d459b8f328b974eca534c: Scheduling FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948): perf score=10.126437
I20260812 06:19:30.016777 29200 maintenance_manager.cc:643] P bf12e818f58d459b8f328b974eca534c: FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948) complete. Timing: real 0.032s	user 0.021s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13478,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:30.017561 29310 maintenance_manager.cc:419] P bf12e818f58d459b8f328b974eca534c: Scheduling FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948): perf score=2.188937
I20260812 06:19:30.043262 29200 maintenance_manager.cc:643] P bf12e818f58d459b8f328b974eca534c: FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948) complete. Timing: real 0.025s	user 0.004s	sys 0.017s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5569,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:30.043944 29310 maintenance_manager.cc:419] P bf12e818f58d459b8f328b974eca534c: Scheduling FlushMRSOp(27bfafbb498d48749a63b4089a642948): perf score=1.000000
I20260812 06:19:30.087801 29200 maintenance_manager.cc:643] P bf12e818f58d459b8f328b974eca534c: FlushMRSOp(27bfafbb498d48749a63b4089a642948) complete. Timing: real 0.044s	user 0.030s	sys 0.005s Metrics: {"bytes_written":1152512,"cfile_init":1,"dirs.queue_time_us":61,"dirs.run_cpu_time_us":191,"dirs.run_wall_time_us":1185,"drs_written":1,"lbm_read_time_us":98,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1434,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:30.088456 29310 maintenance_manager.cc:419] P bf12e818f58d459b8f328b974eca534c: Scheduling UndoDeltaBlockGCOp(27bfafbb498d48749a63b4089a642948): 446 bytes on disk
I20260812 06:19:30.089020 29200 maintenance_manager.cc:643] P bf12e818f58d459b8f328b974eca534c: UndoDeltaBlockGCOp(27bfafbb498d48749a63b4089a642948) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4}
I20260812 06:19:30.089671 29310 maintenance_manager.cc:419] P bf12e818f58d459b8f328b974eca534c: Scheduling FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948): perf score=3.181125
I20260812 06:19:30.102830 29200 maintenance_manager.cc:643] P bf12e818f58d459b8f328b974eca534c: FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948) complete. Timing: real 0.013s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4512901,"delete_count":0,"lbm_write_time_us":4131,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:30.103298 29310 maintenance_manager.cc:419] P bf12e818f58d459b8f328b974eca534c: Scheduling LogGCOp(27bfafbb498d48749a63b4089a642948): free 115943424 bytes of WAL
I20260812 06:19:30.103536 29200 log_reader.cc:385] T 27bfafbb498d48749a63b4089a642948: removed 11 log segments from log reader
I20260812 06:19:30.103605 29200 log.cc:1079] T 27bfafbb498d48749a63b4089a642948 P bf12e818f58d459b8f328b974eca534c: Deleting log segment in path: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560090170-28680-0/minicluster-data/ts-0-root/wals/27bfafbb498d48749a63b4089a642948/wal-000000028 (ops 134-138)
I20260812 06:19:30.103659 29200 log.cc:1079] T 27bfafbb498d48749a63b4089a642948 P bf12e818f58d459b8f328b974eca534c: Deleting log segment in path: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560090170-28680-0/minicluster-data/ts-0-root/wals/27bfafbb498d48749a63b4089a642948/wal-000000029 (ops 139-143)
I20260812 06:19:30.103714 29200 log.cc:1079] T 27bfafbb498d48749a63b4089a642948 P bf12e818f58d459b8f328b974eca534c: Deleting log segment in path: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560090170-28680-0/minicluster-data/ts-0-root/wals/27bfafbb498d48749a63b4089a642948/wal-000000030 (ops 144-148)
I20260812 06:19:30.103761 29200 log.cc:1079] T 27bfafbb498d48749a63b4089a642948 P bf12e818f58d459b8f328b974eca534c: Deleting log segment in path: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560090170-28680-0/minicluster-data/ts-0-root/wals/27bfafbb498d48749a63b4089a642948/wal-000000031 (ops 149-153)
I20260812 06:19:30.103798 29200 log.cc:1079] T 27bfafbb498d48749a63b4089a642948 P bf12e818f58d459b8f328b974eca534c: Deleting log segment in path: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560090170-28680-0/minicluster-data/ts-0-root/wals/27bfafbb498d48749a63b4089a642948/wal-000000032 (ops 154-158)
I20260812 06:19:30.103837 29200 log.cc:1079] T 27bfafbb498d48749a63b4089a642948 P bf12e818f58d459b8f328b974eca534c: Deleting log segment in path: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560090170-28680-0/minicluster-data/ts-0-root/wals/27bfafbb498d48749a63b4089a642948/wal-000000033 (ops 159-163)
I20260812 06:19:30.103875 29200 log.cc:1079] T 27bfafbb498d48749a63b4089a642948 P bf12e818f58d459b8f328b974eca534c: Deleting log segment in path: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560090170-28680-0/minicluster-data/ts-0-root/wals/27bfafbb498d48749a63b4089a642948/wal-000000034 (ops 164-168)
I20260812 06:19:30.103914 29200 log.cc:1079] T 27bfafbb498d48749a63b4089a642948 P bf12e818f58d459b8f328b974eca534c: Deleting log segment in path: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560090170-28680-0/minicluster-data/ts-0-root/wals/27bfafbb498d48749a63b4089a642948/wal-000000035 (ops 169-173)
I20260812 06:19:30.103952 29200 log.cc:1079] T 27bfafbb498d48749a63b4089a642948 P bf12e818f58d459b8f328b974eca534c: Deleting log segment in path: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560090170-28680-0/minicluster-data/ts-0-root/wals/27bfafbb498d48749a63b4089a642948/wal-000000036 (ops 174-178)
I20260812 06:19:30.103989 29200 log.cc:1079] T 27bfafbb498d48749a63b4089a642948 P bf12e818f58d459b8f328b974eca534c: Deleting log segment in path: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560090170-28680-0/minicluster-data/ts-0-root/wals/27bfafbb498d48749a63b4089a642948/wal-000000037 (ops 179-183)
I20260812 06:19:30.104031 29200 log.cc:1079] T 27bfafbb498d48749a63b4089a642948 P bf12e818f58d459b8f328b974eca534c: Deleting log segment in path: /tmp/dist-test-taskA67E7c/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560090170-28680-0/minicluster-data/ts-0-root/wals/27bfafbb498d48749a63b4089a642948/wal-000000038 (ops 184-188)
I20260812 06:19:30.128222 29200 maintenance_manager.cc:643] P bf12e818f58d459b8f328b974eca534c: LogGCOp(27bfafbb498d48749a63b4089a642948) complete. Timing: real 0.025s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:19:30.128782 29310 maintenance_manager.cc:419] P bf12e818f58d459b8f328b974eca534c: Scheduling FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948): perf score=2.188937
I20260812 06:19:30.144244 29200 maintenance_manager.cc:643] P bf12e818f58d459b8f328b974eca534c: FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948) complete. Timing: real 0.015s	user 0.006s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4238,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:30.144706 29310 maintenance_manager.cc:419] P bf12e818f58d459b8f328b974eca534c: Scheduling FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948): perf score=2.188937
I20260812 06:19:30.159111 29200 maintenance_manager.cc:643] P bf12e818f58d459b8f328b974eca534c: FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948) complete. Timing: real 0.014s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5685,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:30.159556 29310 maintenance_manager.cc:419] P bf12e818f58d459b8f328b974eca534c: Scheduling MajorDeltaCompactionOp(27bfafbb498d48749a63b4089a642948): perf score=1.000000
I20260812 06:19:30.385281 28680 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.685s	user 1.772s	sys 0.114s
I20260812 06:19:30.388197 29200 maintenance_manager.cc:643] P bf12e818f58d459b8f328b974eca534c: MajorDeltaCompactionOp(27bfafbb498d48749a63b4089a642948) complete. Timing: real 0.228s	user 0.150s	sys 0.064s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":33020853,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":205,"lbm_read_time_us":14547,"lbm_reads_lt_1ms":775,"lbm_write_time_us":38604,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":14848,"thread_start_us":89,"threads_started":1,"update_count":3500}
I20260812 06:19:30.388813 29310 maintenance_manager.cc:419] P bf12e818f58d459b8f328b974eca534c: Scheduling FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948): perf score=18.063937
I20260812 06:19:30.422184 28680 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.036s	user 0.002s	sys 0.000s
I20260812 06:19:30.422694 28680 tablet_server.cc:179] TabletServer@127.28.2.1:0 shutting down...
I20260812 06:19:30.455262 29200 maintenance_manager.cc:643] P bf12e818f58d459b8f328b974eca534c: FlushDeltaMemStoresOp(27bfafbb498d48749a63b4089a642948) complete. Timing: real 0.066s	user 0.045s	sys 0.019s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":29493,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":502,"reinsert_count":0,"update_count":2500}
I20260812 06:19:30.455822 28680 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:30.456053 28680 tablet_replica.cc:333] T 27bfafbb498d48749a63b4089a642948 P bf12e818f58d459b8f328b974eca534c: stopping tablet replica
I20260812 06:19:30.456198 28680 raft_consensus.cc:2243] T 27bfafbb498d48749a63b4089a642948 P bf12e818f58d459b8f328b974eca534c [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:30.456367 28680 raft_consensus.cc:2272] T 27bfafbb498d48749a63b4089a642948 P bf12e818f58d459b8f328b974eca534c [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:30.459594 28680 tablet_server.cc:196] TabletServer@127.28.2.1:0 shutdown complete.
I20260812 06:19:30.462565 28680 master.cc:562] Master@127.28.2.62:43645 shutting down...
I20260812 06:19:30.469225 28680 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 911a29536579403fa9ad4f9e1c43f421 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:30.469406 28680 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 911a29536579403fa9ad4f9e1c43f421 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:30.469502 28680 tablet_replica.cc:333] T 00000000000000000000000000000000 P 911a29536579403fa9ad4f9e1c43f421: stopping tablet replica
I20260812 06:19:30.481793 28680 master.cc:584] Master@127.28.2.62:43645 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5065 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10470 ms total)

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