[==========] 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:16:55.222241 26474 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.25.218.190:46229
I20260812 06:16:55.223824 26474 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:16:55.224740 26474 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:55.232833 26481 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:16:55.232887 26474 server_base.cc:1061] running on GCE node
W20260812 06:16:55.232833 26480 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:16:55.233242 26483 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:16:55.233985 26474 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:55.234119 26474 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:16:55.234175 26474 hybrid_clock.cc:648] HybridClock initialized: now 1786515415234173 us; error 0 us; skew 500 ppm
I20260812 06:16:55.236868 26474 webserver.cc:533] Webserver started at http://127.25.218.190:42217/ using document root <none> and password file <none>
I20260812 06:16:55.237608 26474 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:55.237686 26474 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:55.238090 26474 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:55.240209 26474 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415209139-26474-0/minicluster-data/master-0-root/instance:
uuid: "27dc43753a084413b82a411b0b6f482e"
format_stamp: "Formatted at 2026-08-12 06:16:55 on dist-test-slave-csg5"
I20260812 06:16:55.244545 26474 fs_manager.cc:696] Time spent creating directory manager: real 0.004s	user 0.005s	sys 0.000s
I20260812 06:16:55.247383 26488 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:16:55.249068 26474 fs_manager.cc:730] Time spent opening block manager: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:16:55.249276 26474 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415209139-26474-0/minicluster-data/master-0-root
uuid: "27dc43753a084413b82a411b0b6f482e"
format_stamp: "Formatted at 2026-08-12 06:16:55 on dist-test-slave-csg5"
I20260812 06:16:55.249457 26474 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415209139-26474-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415209139-26474-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415209139-26474-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:16:55.268978 26474 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:55.269829 26474 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:16:55.270066 26474 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:55.279521 26474 rpc_server.cc:307] RPC server started. Bound to: 127.25.218.190:46229
I20260812 06:16:55.279537 26546 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.25.218.190:46229 every 8 connection(s)
I20260812 06:16:55.282246 26547 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:16:55.288380 26547 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 27dc43753a084413b82a411b0b6f482e: Bootstrap starting.
I20260812 06:16:55.291035 26547 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 27dc43753a084413b82a411b0b6f482e: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:55.292109 26547 log.cc:826] T 00000000000000000000000000000000 P 27dc43753a084413b82a411b0b6f482e: Log is configured to *not* fsync() on all Append() calls
I20260812 06:16:55.294459 26547 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 27dc43753a084413b82a411b0b6f482e: No bootstrap required, opened a new log
I20260812 06:16:55.298215 26547 raft_consensus.cc:359] T 00000000000000000000000000000000 P 27dc43753a084413b82a411b0b6f482e [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "27dc43753a084413b82a411b0b6f482e" member_type: VOTER }
I20260812 06:16:55.298539 26547 raft_consensus.cc:385] T 00000000000000000000000000000000 P 27dc43753a084413b82a411b0b6f482e [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:55.298712 26547 raft_consensus.cc:740] T 00000000000000000000000000000000 P 27dc43753a084413b82a411b0b6f482e [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 27dc43753a084413b82a411b0b6f482e, State: Initialized, Role: FOLLOWER
I20260812 06:16:55.299640 26547 consensus_queue.cc:260] T 00000000000000000000000000000000 P 27dc43753a084413b82a411b0b6f482e [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: "27dc43753a084413b82a411b0b6f482e" member_type: VOTER }
I20260812 06:16:55.299901 26547 raft_consensus.cc:399] T 00000000000000000000000000000000 P 27dc43753a084413b82a411b0b6f482e [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:55.300011 26547 raft_consensus.cc:493] T 00000000000000000000000000000000 P 27dc43753a084413b82a411b0b6f482e [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:55.300200 26547 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 27dc43753a084413b82a411b0b6f482e [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:55.301309 26547 raft_consensus.cc:515] T 00000000000000000000000000000000 P 27dc43753a084413b82a411b0b6f482e [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "27dc43753a084413b82a411b0b6f482e" member_type: VOTER }
I20260812 06:16:55.301879 26547 leader_election.cc:304] T 00000000000000000000000000000000 P 27dc43753a084413b82a411b0b6f482e [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: 27dc43753a084413b82a411b0b6f482e; no voters: 
I20260812 06:16:55.302332 26547 leader_election.cc:290] T 00000000000000000000000000000000 P 27dc43753a084413b82a411b0b6f482e [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:55.302572 26550 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 27dc43753a084413b82a411b0b6f482e [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:55.302947 26550 raft_consensus.cc:697] T 00000000000000000000000000000000 P 27dc43753a084413b82a411b0b6f482e [term 1 LEADER]: Becoming Leader. State: Replica: 27dc43753a084413b82a411b0b6f482e, State: Running, Role: LEADER
I20260812 06:16:55.303561 26550 consensus_queue.cc:237] T 00000000000000000000000000000000 P 27dc43753a084413b82a411b0b6f482e [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: "27dc43753a084413b82a411b0b6f482e" member_type: VOTER }
I20260812 06:16:55.303639 26547 sys_catalog.cc:565] T 00000000000000000000000000000000 P 27dc43753a084413b82a411b0b6f482e [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:55.305938 26551 sys_catalog.cc:455] T 00000000000000000000000000000000 P 27dc43753a084413b82a411b0b6f482e [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "27dc43753a084413b82a411b0b6f482e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "27dc43753a084413b82a411b0b6f482e" member_type: VOTER } }
I20260812 06:16:55.306123 26551 sys_catalog.cc:458] T 00000000000000000000000000000000 P 27dc43753a084413b82a411b0b6f482e [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:55.306447 26552 sys_catalog.cc:455] T 00000000000000000000000000000000 P 27dc43753a084413b82a411b0b6f482e [sys.catalog]: SysCatalogTable state changed. Reason: New leader 27dc43753a084413b82a411b0b6f482e. Latest consensus state: current_term: 1 leader_uuid: "27dc43753a084413b82a411b0b6f482e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "27dc43753a084413b82a411b0b6f482e" member_type: VOTER } }
I20260812 06:16:55.306499 26567 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:55.306564 26474 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:55.306564 26552 sys_catalog.cc:458] T 00000000000000000000000000000000 P 27dc43753a084413b82a411b0b6f482e [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:55.309428 26567 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:55.315595 26567 catalog_manager.cc:1383] Generated new cluster ID: 86b1c27cb04a4053a44ff5f80f8cbeed
I20260812 06:16:55.315718 26567 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:55.324442 26567 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:55.325510 26567 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:55.339684 26567 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 27dc43753a084413b82a411b0b6f482e: Generated new TSK 0
I20260812 06:16:55.340598 26567 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:55.371857 26474 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:16:55.375926 26474 server_base.cc:1061] running on GCE node
W20260812 06:16:55.376157 26572 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:16:55.376209 26575 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:16:55.376058 26573 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:16:55.376600 26474 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:55.376678 26474 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:16:55.376708 26474 hybrid_clock.cc:648] HybridClock initialized: now 1786515415376707 us; error 0 us; skew 500 ppm
I20260812 06:16:55.378029 26474 webserver.cc:533] Webserver started at http://127.25.218.129:39715/ using document root <none> and password file <none>
I20260812 06:16:55.378248 26474 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:55.378324 26474 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:55.378443 26474 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:55.378970 26474 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415209139-26474-0/minicluster-data/ts-0-root/instance:
uuid: "e986ddf3938f4149b50fb75978f8378d"
format_stamp: "Formatted at 2026-08-12 06:16:55 on dist-test-slave-csg5"
I20260812 06:16:55.380750 26474 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:16:55.382052 26582 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:16:55.382480 26474 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:16:55.382570 26474 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415209139-26474-0/minicluster-data/ts-0-root
uuid: "e986ddf3938f4149b50fb75978f8378d"
format_stamp: "Formatted at 2026-08-12 06:16:55 on dist-test-slave-csg5"
I20260812 06:16:55.382778 26474 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415209139-26474-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415209139-26474-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415209139-26474-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:16:55.397450 26474 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:55.398038 26474 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:55.399819 26474 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:55.401087 26474 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:55.401168 26474 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:55.401223 26474 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:55.401278 26474 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:55.410965 26474 rpc_server.cc:307] RPC server started. Bound to: 127.25.218.129:32797
I20260812 06:16:55.411038 26650 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.25.218.129:32797 every 8 connection(s)
I20260812 06:16:55.423846 26651 heartbeater.cc:344] Connected to a master server at 127.25.218.190:46229
I20260812 06:16:55.424189 26651 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:55.424836 26651 heartbeater.cc:507] Master 127.25.218.190:46229 requested a full tablet report, sending...
I20260812 06:16:55.426884 26506 ts_manager.cc:194] Registered new tserver with Master: e986ddf3938f4149b50fb75978f8378d (127.25.218.129:32797)
I20260812 06:16:55.427042 26474 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.015342735s
I20260812 06:16:55.428707 26506 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:43776
I20260812 06:16:55.440338 26506 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:43786:
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:16:55.460048 26611 tablet_service.cc:1511] Processing CreateTablet for tablet 99b390d6452642a486239b8669e521ef (DEFAULT_TABLE table=heavy-update-compaction-test [id=6ceba74e6ce342feb00db31c3179a891]), partition=
I20260812 06:16:55.460675 26611 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 99b390d6452642a486239b8669e521ef. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:55.466190 26663 tablet_bootstrap.cc:492] T 99b390d6452642a486239b8669e521ef P e986ddf3938f4149b50fb75978f8378d: Bootstrap starting.
I20260812 06:16:55.467723 26663 tablet_bootstrap.cc:654] T 99b390d6452642a486239b8669e521ef P e986ddf3938f4149b50fb75978f8378d: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:55.469151 26663 tablet_bootstrap.cc:492] T 99b390d6452642a486239b8669e521ef P e986ddf3938f4149b50fb75978f8378d: No bootstrap required, opened a new log
I20260812 06:16:55.469430 26663 ts_tablet_manager.cc:1403] T 99b390d6452642a486239b8669e521ef P e986ddf3938f4149b50fb75978f8378d: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:16:55.469976 26663 raft_consensus.cc:359] T 99b390d6452642a486239b8669e521ef P e986ddf3938f4149b50fb75978f8378d [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e986ddf3938f4149b50fb75978f8378d" member_type: VOTER last_known_addr { host: "127.25.218.129" port: 32797 } }
I20260812 06:16:55.470140 26663 raft_consensus.cc:385] T 99b390d6452642a486239b8669e521ef P e986ddf3938f4149b50fb75978f8378d [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:55.470212 26663 raft_consensus.cc:740] T 99b390d6452642a486239b8669e521ef P e986ddf3938f4149b50fb75978f8378d [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: e986ddf3938f4149b50fb75978f8378d, State: Initialized, Role: FOLLOWER
I20260812 06:16:55.470424 26663 consensus_queue.cc:260] T 99b390d6452642a486239b8669e521ef P e986ddf3938f4149b50fb75978f8378d [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: "e986ddf3938f4149b50fb75978f8378d" member_type: VOTER last_known_addr { host: "127.25.218.129" port: 32797 } }
I20260812 06:16:55.470958 26663 raft_consensus.cc:399] T 99b390d6452642a486239b8669e521ef P e986ddf3938f4149b50fb75978f8378d [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:55.471040 26663 raft_consensus.cc:493] T 99b390d6452642a486239b8669e521ef P e986ddf3938f4149b50fb75978f8378d [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:55.471103 26663 raft_consensus.cc:3060] T 99b390d6452642a486239b8669e521ef P e986ddf3938f4149b50fb75978f8378d [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:55.472116 26663 raft_consensus.cc:515] T 99b390d6452642a486239b8669e521ef P e986ddf3938f4149b50fb75978f8378d [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e986ddf3938f4149b50fb75978f8378d" member_type: VOTER last_known_addr { host: "127.25.218.129" port: 32797 } }
I20260812 06:16:55.472308 26663 leader_election.cc:304] T 99b390d6452642a486239b8669e521ef P e986ddf3938f4149b50fb75978f8378d [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: e986ddf3938f4149b50fb75978f8378d; no voters: 
I20260812 06:16:55.472594 26663 leader_election.cc:290] T 99b390d6452642a486239b8669e521ef P e986ddf3938f4149b50fb75978f8378d [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:55.473016 26663 ts_tablet_manager.cc:1434] T 99b390d6452642a486239b8669e521ef P e986ddf3938f4149b50fb75978f8378d: Time spent starting tablet: real 0.003s	user 0.004s	sys 0.000s
I20260812 06:16:55.473090 26665 raft_consensus.cc:2804] T 99b390d6452642a486239b8669e521ef P e986ddf3938f4149b50fb75978f8378d [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:55.473268 26651 heartbeater.cc:499] Master 127.25.218.190:46229 was elected leader, sending a full tablet report...
I20260812 06:16:55.473489 26665 raft_consensus.cc:697] T 99b390d6452642a486239b8669e521ef P e986ddf3938f4149b50fb75978f8378d [term 1 LEADER]: Becoming Leader. State: Replica: e986ddf3938f4149b50fb75978f8378d, State: Running, Role: LEADER
I20260812 06:16:55.473706 26665 consensus_queue.cc:237] T 99b390d6452642a486239b8669e521ef P e986ddf3938f4149b50fb75978f8378d [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: "e986ddf3938f4149b50fb75978f8378d" member_type: VOTER last_known_addr { host: "127.25.218.129" port: 32797 } }
I20260812 06:16:55.477839 26506 catalog_manager.cc:5719] T 99b390d6452642a486239b8669e521ef P e986ddf3938f4149b50fb75978f8378d reported cstate change: term changed from 0 to 1, leader changed from <none> to e986ddf3938f4149b50fb75978f8378d (127.25.218.129). New cstate: current_term: 1 leader_uuid: "e986ddf3938f4149b50fb75978f8378d" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e986ddf3938f4149b50fb75978f8378d" member_type: VOTER last_known_addr { host: "127.25.218.129" port: 32797 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:55.553038 26474 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.062s	user 0.018s	sys 0.010s
I20260812 06:16:55.662603 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling FlushMRSOp(99b390d6452642a486239b8669e521ef): perf score=15.086190
I20260812 06:16:55.875169 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: FlushMRSOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.212s	user 0.166s	sys 0.045s Metrics: {"bytes_written":8615323,"cfile_init":1,"compiler_manager_pool.queue_time_us":225,"delete_count":0,"dirs.queue_time_us":82,"dirs.run_cpu_time_us":287,"dirs.run_wall_time_us":1262,"drs_written":1,"lbm_read_time_us":176,"lbm_reads_lt_1ms":4,"lbm_write_time_us":50878,"lbm_writes_lt_1ms":567,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"thread_start_us":139,"threads_started":1,"update_count":1050}
I20260812 06:16:55.876863 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling LogGCOp(99b390d6452642a486239b8669e521ef): free 11976772 bytes of WAL
I20260812 06:16:55.877362 26588 log_reader.cc:385] T 99b390d6452642a486239b8669e521ef: removed 1 log segments from log reader
I20260812 06:16:55.877483 26588 log.cc:1079] T 99b390d6452642a486239b8669e521ef P e986ddf3938f4149b50fb75978f8378d: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/99b390d6452642a486239b8669e521ef/wal-000000001 (ops 1-6)
I20260812 06:16:55.880889 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: LogGCOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.004s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:16:55.881426 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling UndoDeltaBlockGCOp(99b390d6452642a486239b8669e521ef): 12308958 bytes on disk
I20260812 06:16:55.882239 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: UndoDeltaBlockGCOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":73,"lbm_reads_lt_1ms":4}
I20260812 06:16:55.883244 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef): perf score=2.188937
I20260812 06:16:55.910068 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.027s	user 0.012s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":8931,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:55.910892 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling MajorDeltaCompactionOp(99b390d6452642a486239b8669e521ef): perf score=1.000000
I20260812 06:16:56.103582 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: MajorDeltaCompactionOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.192s	user 0.133s	sys 0.053s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16528891,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":530,"lbm_read_time_us":9627,"lbm_reads_lt_1ms":364,"lbm_write_time_us":37830,"lbm_writes_lt_1ms":343,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":269,"threads_started":5,"update_count":1500}
I20260812 06:16:56.104194 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef): perf score=7.149875
I20260812 06:16:56.137391 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.033s	user 0.026s	sys 0.004s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":14104,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:16:56.138000 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef): perf score=2.188937
I20260812 06:16:56.150108 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4469,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:56.150816 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling MajorDeltaCompactionOp(99b390d6452642a486239b8669e521ef): perf score=1.000000
I20260812 06:16:56.313982 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: MajorDeltaCompactionOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.163s	user 0.101s	sys 0.045s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16528891,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":556,"lbm_read_time_us":8605,"lbm_reads_lt_1ms":372,"lbm_write_time_us":25528,"lbm_writes_lt_1ms":343,"mutex_wait_us":51,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":19072,"update_count":1500}
I20260812 06:16:56.315092 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef): perf score=10.126437
I20260812 06:16:56.401510 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.086s	user 0.036s	sys 0.021s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":26001,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:56.402516 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef): perf score=2.188937
I20260812 06:16:56.424253 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.021s	user 0.007s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7655,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:56.425177 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling MajorDeltaCompactionOp(99b390d6452642a486239b8669e521ef): perf score=1.000000
I20260812 06:16:56.629011 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: MajorDeltaCompactionOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.203s	user 0.155s	sys 0.047s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":357,"lbm_read_time_us":13921,"lbm_reads_lt_1ms":472,"lbm_write_time_us":41636,"lbm_writes_lt_1ms":443,"mutex_wait_us":76,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8960,"update_count":2000}
I20260812 06:16:56.629828 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef): perf score=10.126437
I20260812 06:16:56.710727 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.081s	user 0.044s	sys 0.036s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":36499,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:16:56.711745 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef): perf score=2.188937
I20260812 06:16:56.732954 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.021s	user 0.009s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7295,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:56.733822 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling MajorDeltaCompactionOp(99b390d6452642a486239b8669e521ef): perf score=1.000000
I20260812 06:16:56.945541 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: MajorDeltaCompactionOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.211s	user 0.183s	sys 0.027s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":536,"lbm_read_time_us":16694,"lbm_reads_lt_1ms":472,"lbm_write_time_us":43172,"lbm_writes_lt_1ms":443,"mutex_wait_us":51,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12288,"update_count":2000}
I20260812 06:16:56.946725 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef): perf score=10.126437
I20260812 06:16:57.010079 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.063s	user 0.029s	sys 0.028s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":26650,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:57.011039 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef): perf score=2.188937
I20260812 06:16:57.037671 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.026s	user 0.019s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":10028,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:57.038429 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling MajorDeltaCompactionOp(99b390d6452642a486239b8669e521ef): perf score=1.000000
I20260812 06:16:57.249357 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: MajorDeltaCompactionOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.211s	user 0.170s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":748,"lbm_read_time_us":16480,"lbm_reads_lt_1ms":472,"lbm_write_time_us":39711,"lbm_writes_lt_1ms":443,"mutex_wait_us":44,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":15232,"update_count":2000}
I20260812 06:16:57.250485 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef): perf score=10.126437
I20260812 06:16:57.332406 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.082s	user 0.037s	sys 0.027s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":24482,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:57.333474 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef): perf score=2.188937
I20260812 06:16:57.355598 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.022s	user 0.017s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":8944,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:57.356323 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling MajorDeltaCompactionOp(99b390d6452642a486239b8669e521ef): perf score=1.000000
I20260812 06:16:57.618245 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: MajorDeltaCompactionOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.262s	user 0.194s	sys 0.068s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":668,"lbm_read_time_us":18927,"lbm_reads_lt_1ms":472,"lbm_write_time_us":49109,"lbm_writes_lt_1ms":443,"mutex_wait_us":85,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":24832,"update_count":2000}
I20260812 06:16:57.619647 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef): perf score=10.126437
I20260812 06:16:57.707119 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.087s	user 0.055s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":32184,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:57.708056 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef): perf score=2.188937
I20260812 06:16:57.728950 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.021s	user 0.011s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":8025,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:57.729735 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling MajorDeltaCompactionOp(99b390d6452642a486239b8669e521ef): perf score=1.000000
I20260812 06:16:57.952551 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: MajorDeltaCompactionOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.223s	user 0.195s	sys 0.027s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1074,"lbm_read_time_us":12850,"lbm_reads_lt_1ms":472,"lbm_write_time_us":50015,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":64,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":58368,"update_count":2000}
I20260812 06:16:57.954257 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef): perf score=10.126437
I20260812 06:16:58.027470 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.073s	user 0.046s	sys 0.025s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":32741,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:58.028522 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef): perf score=2.188937
I20260812 06:16:58.040570 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.012s	user 0.001s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4548,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:58.041311 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling FlushMRSOp(99b390d6452642a486239b8669e521ef): perf score=1.000000
I20260812 06:16:58.072124 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: FlushMRSOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.031s	user 0.028s	sys 0.001s Metrics: {"bytes_written":1234474,"cfile_init":1,"dirs.queue_time_us":84,"dirs.run_cpu_time_us":304,"dirs.run_wall_time_us":1723,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1793,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:16:58.073449 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling LogGCOp(99b390d6452642a486239b8669e521ef): free 121006367 bytes of WAL
I20260812 06:16:58.073810 26588 log_reader.cc:385] T 99b390d6452642a486239b8669e521ef: removed 12 log segments from log reader
I20260812 06:16:58.073886 26588 log.cc:1079] T 99b390d6452642a486239b8669e521ef P e986ddf3938f4149b50fb75978f8378d: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/99b390d6452642a486239b8669e521ef/wal-000000002 (ops 7-11)
I20260812 06:16:58.073930 26588 log.cc:1079] T 99b390d6452642a486239b8669e521ef P e986ddf3938f4149b50fb75978f8378d: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/99b390d6452642a486239b8669e521ef/wal-000000003 (ops 12-16)
I20260812 06:16:58.073956 26588 log.cc:1079] T 99b390d6452642a486239b8669e521ef P e986ddf3938f4149b50fb75978f8378d: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/99b390d6452642a486239b8669e521ef/wal-000000004 (ops 17-21)
I20260812 06:16:58.073982 26588 log.cc:1079] T 99b390d6452642a486239b8669e521ef P e986ddf3938f4149b50fb75978f8378d: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/99b390d6452642a486239b8669e521ef/wal-000000005 (ops 22-26)
I20260812 06:16:58.074008 26588 log.cc:1079] T 99b390d6452642a486239b8669e521ef P e986ddf3938f4149b50fb75978f8378d: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/99b390d6452642a486239b8669e521ef/wal-000000006 (ops 27-31)
I20260812 06:16:58.074033 26588 log.cc:1079] T 99b390d6452642a486239b8669e521ef P e986ddf3938f4149b50fb75978f8378d: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/99b390d6452642a486239b8669e521ef/wal-000000007 (ops 32-36)
I20260812 06:16:58.074065 26588 log.cc:1079] T 99b390d6452642a486239b8669e521ef P e986ddf3938f4149b50fb75978f8378d: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/99b390d6452642a486239b8669e521ef/wal-000000008 (ops 37-41)
I20260812 06:16:58.074088 26588 log.cc:1079] T 99b390d6452642a486239b8669e521ef P e986ddf3938f4149b50fb75978f8378d: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/99b390d6452642a486239b8669e521ef/wal-000000009 (ops 42-46)
I20260812 06:16:58.074110 26588 log.cc:1079] T 99b390d6452642a486239b8669e521ef P e986ddf3938f4149b50fb75978f8378d: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/99b390d6452642a486239b8669e521ef/wal-000000010 (ops 47-51)
I20260812 06:16:58.074132 26588 log.cc:1079] T 99b390d6452642a486239b8669e521ef P e986ddf3938f4149b50fb75978f8378d: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/99b390d6452642a486239b8669e521ef/wal-000000011 (ops 52-56)
I20260812 06:16:58.074164 26588 log.cc:1079] T 99b390d6452642a486239b8669e521ef P e986ddf3938f4149b50fb75978f8378d: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/99b390d6452642a486239b8669e521ef/wal-000000012 (ops 57-60)
I20260812 06:16:58.074200 26588 log.cc:1079] T 99b390d6452642a486239b8669e521ef P e986ddf3938f4149b50fb75978f8378d: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/99b390d6452642a486239b8669e521ef/wal-000000013 (ops 61-65)
I20260812 06:16:58.103427 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: LogGCOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.030s	user 0.001s	sys 0.028s Metrics: {}
I20260812 06:16:58.103931 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef): perf score=3.181125
I20260812 06:16:58.124204 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.020s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4850,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:58.124727 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef): perf score=2.188937
I20260812 06:16:58.135082 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3737,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:58.135612 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling MajorDeltaCompactionOp(99b390d6452642a486239b8669e521ef): perf score=1.000000
I20260812 06:16:58.316191 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: MajorDeltaCompactionOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.180s	user 0.109s	sys 0.068s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836363,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":801,"lbm_read_time_us":12477,"lbm_reads_lt_1ms":674,"lbm_write_time_us":37346,"lbm_writes_lt_1ms":643,"mutex_wait_us":331,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":4224,"thread_start_us":81,"threads_started":1,"update_count":3000}
I20260812 06:16:58.316761 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef): perf score=14.095187
I20260812 06:16:58.377051 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.060s	user 0.034s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23702,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:58.377761 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef): perf score=2.188937
I20260812 06:16:58.395395 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.017s	user 0.013s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6365,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:58.396206 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling UndoDeltaBlockGCOp(99b390d6452642a486239b8669e521ef): 473 bytes on disk
I20260812 06:16:58.396955 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: UndoDeltaBlockGCOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":134,"lbm_reads_lt_1ms":4}
I20260812 06:16:58.397876 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling MajorDeltaCompactionOp(99b390d6452642a486239b8669e521ef): perf score=1.000000
I20260812 06:16:58.570694 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: MajorDeltaCompactionOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.173s	user 0.151s	sys 0.022s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":159,"lbm_read_time_us":12308,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32240,"lbm_writes_lt_1ms":543,"mutex_wait_us":74,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":2500}
I20260812 06:16:58.571360 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef): perf score=10.126437
I20260812 06:16:58.619107 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.048s	user 0.021s	sys 0.026s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20443,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":14208,"update_count":1500}
I20260812 06:16:58.619803 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef): perf score=2.188937
I20260812 06:16:58.633184 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.013s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4843,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:58.633898 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling MajorDeltaCompactionOp(99b390d6452642a486239b8669e521ef): perf score=1.000000
I20260812 06:16:58.807389 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: MajorDeltaCompactionOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.173s	user 0.117s	sys 0.052s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":882,"lbm_read_time_us":10429,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29427,"lbm_writes_lt_1ms":443,"mutex_wait_us":58,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2000}
I20260812 06:16:58.807933 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef): perf score=11.118625
I20260812 06:16:58.846714 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.039s	user 0.030s	sys 0.005s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16447,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:58.847234 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef): perf score=2.188937
I20260812 06:16:58.882993 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.036s	user 0.012s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5378,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:58.883574 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef): perf score=2.188937
I20260812 06:16:58.895488 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.012s	user 0.005s	sys 0.006s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4492,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:58.896092 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling MajorDeltaCompactionOp(99b390d6452642a486239b8669e521ef): perf score=1.000000
I20260812 06:16:59.092103 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: MajorDeltaCompactionOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.196s	user 0.144s	sys 0.051s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733833,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":286,"lbm_read_time_us":14818,"lbm_reads_lt_1ms":573,"lbm_write_time_us":33478,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:16:59.092828 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef): perf score=10.126437
I20260812 06:16:59.144204 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.051s	user 0.029s	sys 0.020s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":23057,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:16:59.145009 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef): perf score=2.188937
I20260812 06:16:59.164148 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.019s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6129,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:59.164763 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling MajorDeltaCompactionOp(99b390d6452642a486239b8669e521ef): perf score=1.000000
I20260812 06:16:59.295226 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: MajorDeltaCompactionOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.130s	user 0.107s	sys 0.023s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":297,"lbm_read_time_us":9067,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25932,"lbm_writes_lt_1ms":443,"mutex_wait_us":35,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":41728,"update_count":2000}
I20260812 06:16:59.296135 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef): perf score=10.126437
I20260812 06:16:59.341531 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.045s	user 0.026s	sys 0.016s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":20307,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:16:59.342296 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef): perf score=2.188937
I20260812 06:16:59.359458 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.017s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6652,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:59.360016 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling MajorDeltaCompactionOp(99b390d6452642a486239b8669e521ef): perf score=1.000000
I20260812 06:16:59.496219 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: MajorDeltaCompactionOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.136s	user 0.114s	sys 0.022s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":157,"lbm_read_time_us":7579,"lbm_reads_lt_1ms":468,"lbm_write_time_us":27023,"lbm_writes_lt_1ms":443,"mutex_wait_us":37,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13696,"update_count":2000}
I20260812 06:16:59.497210 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef): perf score=10.126437
I20260812 06:16:59.541502 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.044s	user 0.020s	sys 0.021s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":21221,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:16:59.542104 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef): perf score=2.188937
I20260812 06:16:59.556252 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.014s	user 0.005s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4882,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:59.556922 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling FlushMRSOp(99b390d6452642a486239b8669e521ef): perf score=1.000000
I20260812 06:16:59.590747 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: FlushMRSOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.034s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1152514,"cfile_init":1,"dirs.queue_time_us":134,"dirs.run_cpu_time_us":347,"dirs.run_wall_time_us":2821,"drs_written":1,"lbm_read_time_us":41,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1420,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:16:59.591521 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling LogGCOp(99b390d6452642a486239b8669e521ef): free 124710349 bytes of WAL
I20260812 06:16:59.591817 26588 log_reader.cc:385] T 99b390d6452642a486239b8669e521ef: removed 12 log segments from log reader
I20260812 06:16:59.591892 26588 log.cc:1079] T 99b390d6452642a486239b8669e521ef P e986ddf3938f4149b50fb75978f8378d: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/99b390d6452642a486239b8669e521ef/wal-000000014 (ops 66-70)
I20260812 06:16:59.591933 26588 log.cc:1079] T 99b390d6452642a486239b8669e521ef P e986ddf3938f4149b50fb75978f8378d: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/99b390d6452642a486239b8669e521ef/wal-000000015 (ops 71-75)
I20260812 06:16:59.591964 26588 log.cc:1079] T 99b390d6452642a486239b8669e521ef P e986ddf3938f4149b50fb75978f8378d: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/99b390d6452642a486239b8669e521ef/wal-000000016 (ops 76-80)
I20260812 06:16:59.591995 26588 log.cc:1079] T 99b390d6452642a486239b8669e521ef P e986ddf3938f4149b50fb75978f8378d: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/99b390d6452642a486239b8669e521ef/wal-000000017 (ops 81-85)
I20260812 06:16:59.592020 26588 log.cc:1079] T 99b390d6452642a486239b8669e521ef P e986ddf3938f4149b50fb75978f8378d: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/99b390d6452642a486239b8669e521ef/wal-000000018 (ops 86-90)
I20260812 06:16:59.592046 26588 log.cc:1079] T 99b390d6452642a486239b8669e521ef P e986ddf3938f4149b50fb75978f8378d: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/99b390d6452642a486239b8669e521ef/wal-000000019 (ops 91-95)
I20260812 06:16:59.592077 26588 log.cc:1079] T 99b390d6452642a486239b8669e521ef P e986ddf3938f4149b50fb75978f8378d: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/99b390d6452642a486239b8669e521ef/wal-000000020 (ops 96-100)
I20260812 06:16:59.592108 26588 log.cc:1079] T 99b390d6452642a486239b8669e521ef P e986ddf3938f4149b50fb75978f8378d: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/99b390d6452642a486239b8669e521ef/wal-000000021 (ops 101-105)
I20260812 06:16:59.592137 26588 log.cc:1079] T 99b390d6452642a486239b8669e521ef P e986ddf3938f4149b50fb75978f8378d: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/99b390d6452642a486239b8669e521ef/wal-000000022 (ops 106-110)
I20260812 06:16:59.592166 26588 log.cc:1079] T 99b390d6452642a486239b8669e521ef P e986ddf3938f4149b50fb75978f8378d: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/99b390d6452642a486239b8669e521ef/wal-000000023 (ops 111-115)
I20260812 06:16:59.592198 26588 log.cc:1079] T 99b390d6452642a486239b8669e521ef P e986ddf3938f4149b50fb75978f8378d: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/99b390d6452642a486239b8669e521ef/wal-000000024 (ops 116-120)
I20260812 06:16:59.592243 26588 log.cc:1079] T 99b390d6452642a486239b8669e521ef P e986ddf3938f4149b50fb75978f8378d: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/99b390d6452642a486239b8669e521ef/wal-000000025 (ops 121-125)
I20260812 06:16:59.627213 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: LogGCOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.035s	user 0.000s	sys 0.035s Metrics: {}
I20260812 06:16:59.627774 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef): perf score=2.188937
I20260812 06:16:59.654956 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.027s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4225735,"delete_count":0,"lbm_write_time_us":6240,"lbm_writes_lt_1ms":106,"mutex_wait_us":216,"reinsert_count":0,"update_count":515}
I20260812 06:16:59.655428 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling UndoDeltaBlockGCOp(99b390d6452642a486239b8669e521ef): 447 bytes on disk
I20260812 06:16:59.655875 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: UndoDeltaBlockGCOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":65,"lbm_reads_lt_1ms":4}
I20260812 06:16:59.656358 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef): perf score=2.188937
I20260812 06:16:59.667181 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":3979584,"delete_count":0,"lbm_write_time_us":4022,"lbm_writes_lt_1ms":100,"reinsert_count":0,"update_count":485}
I20260812 06:16:59.667954 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling MajorDeltaCompactionOp(99b390d6452642a486239b8669e521ef): perf score=1.000000
I20260812 06:16:59.859083 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: MajorDeltaCompactionOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.191s	user 0.139s	sys 0.039s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836375,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":2717,"lbm_read_time_us":14067,"lbm_reads_lt_1ms":674,"lbm_write_time_us":36368,"lbm_writes_lt_1ms":643,"mutex_wait_us":2188,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":4352,"thread_start_us":101,"threads_started":1,"update_count":3000}
I20260812 06:16:59.859895 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef): perf score=14.095187
I20260812 06:16:59.930307 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.070s	user 0.059s	sys 0.008s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":32787,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:16:59.931015 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef): perf score=2.188937
I20260812 06:16:59.945309 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5319,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:59.945984 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling MajorDeltaCompactionOp(99b390d6452642a486239b8669e521ef): perf score=1.000000
I20260812 06:17:00.121801 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: MajorDeltaCompactionOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.176s	user 0.122s	sys 0.045s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733726,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":243,"lbm_read_time_us":12156,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34304,"lbm_writes_lt_1ms":543,"mutex_wait_us":36,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":2500}
I20260812 06:17:00.122522 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef): perf score=14.095187
I20260812 06:17:00.186479 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.064s	user 0.032s	sys 0.028s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":27940,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:17:00.187127 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef): perf score=2.188937
I20260812 06:17:00.200053 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.013s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4520,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:00.200826 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling MajorDeltaCompactionOp(99b390d6452642a486239b8669e521ef): perf score=1.000000
I20260812 06:17:00.391904 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: MajorDeltaCompactionOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.191s	user 0.137s	sys 0.050s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733725,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":822,"lbm_read_time_us":10950,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34004,"lbm_writes_lt_1ms":543,"mutex_wait_us":1,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:00.392719 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef): perf score=14.095187
I20260812 06:17:00.466375 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.073s	user 0.037s	sys 0.016s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":25650,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:00.466964 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef): perf score=2.188937
I20260812 06:17:00.479183 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4433,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:00.479938 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling MajorDeltaCompactionOp(99b390d6452642a486239b8669e521ef): perf score=1.000000
I20260812 06:17:00.672549 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: MajorDeltaCompactionOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.192s	user 0.140s	sys 0.046s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733726,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":679,"lbm_read_time_us":13289,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32994,"lbm_writes_lt_1ms":543,"mutex_wait_us":225,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":20992,"update_count":2500}
I20260812 06:17:00.673310 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef): perf score=14.095187
I20260812 06:17:00.739670 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.066s	user 0.038s	sys 0.017s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22947,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:00.740494 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef): perf score=2.188937
I20260812 06:17:00.762828 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.022s	user 0.015s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":8034,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:00.763411 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling MajorDeltaCompactionOp(99b390d6452642a486239b8669e521ef): perf score=1.000000
I20260812 06:17:00.957015 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: MajorDeltaCompactionOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.193s	user 0.143s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":405,"lbm_read_time_us":13715,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34729,"lbm_writes_lt_1ms":543,"mutex_wait_us":3,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8832,"update_count":2500}
I20260812 06:17:00.957712 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef): perf score=14.095187
I20260812 06:17:01.026837 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.069s	user 0.018s	sys 0.051s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25733,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:01.027489 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef): perf score=2.188937
I20260812 06:17:01.042016 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5761,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:01.042594 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling MajorDeltaCompactionOp(99b390d6452642a486239b8669e521ef): perf score=1.000000
I20260812 06:17:01.245276 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: MajorDeltaCompactionOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.202s	user 0.129s	sys 0.069s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733722,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":591,"lbm_read_time_us":15097,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33058,"lbm_writes_lt_1ms":543,"mutex_wait_us":257,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9856,"update_count":2500}
I20260812 06:17:01.246168 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef): perf score=11.118625
I20260812 06:17:01.294766 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.048s	user 0.033s	sys 0.016s Metrics: {"bytes_written":12717738,"delete_count":0,"lbm_write_time_us":20717,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:01.295539 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef): perf score=2.188937
I20260812 06:17:01.329655 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.034s	user 0.014s	sys 0.010s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":7211,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:01.330358 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef): perf score=2.188937
I20260812 06:17:01.342468 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4553,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:01.343078 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling FlushMRSOp(99b390d6452642a486239b8669e521ef): perf score=1.000000
I20260812 06:17:01.387764 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: FlushMRSOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.044s	user 0.037s	sys 0.001s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":125,"dirs.run_cpu_time_us":314,"dirs.run_wall_time_us":1949,"drs_written":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1720,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:17:01.388588 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling LogGCOp(99b390d6452642a486239b8669e521ef): free 132571586 bytes of WAL
I20260812 06:17:01.388844 26588 log_reader.cc:385] T 99b390d6452642a486239b8669e521ef: removed 13 log segments from log reader
I20260812 06:17:01.388921 26588 log.cc:1079] T 99b390d6452642a486239b8669e521ef P e986ddf3938f4149b50fb75978f8378d: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/99b390d6452642a486239b8669e521ef/wal-000000026 (ops 126-130)
I20260812 06:17:01.388981 26588 log.cc:1079] T 99b390d6452642a486239b8669e521ef P e986ddf3938f4149b50fb75978f8378d: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/99b390d6452642a486239b8669e521ef/wal-000000027 (ops 131-135)
I20260812 06:17:01.389031 26588 log.cc:1079] T 99b390d6452642a486239b8669e521ef P e986ddf3938f4149b50fb75978f8378d: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/99b390d6452642a486239b8669e521ef/wal-000000028 (ops 136-140)
I20260812 06:17:01.389052 26588 log.cc:1079] T 99b390d6452642a486239b8669e521ef P e986ddf3938f4149b50fb75978f8378d: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/99b390d6452642a486239b8669e521ef/wal-000000029 (ops 141-145)
I20260812 06:17:01.389110 26588 log.cc:1079] T 99b390d6452642a486239b8669e521ef P e986ddf3938f4149b50fb75978f8378d: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/99b390d6452642a486239b8669e521ef/wal-000000030 (ops 146-150)
I20260812 06:17:01.389154 26588 log.cc:1079] T 99b390d6452642a486239b8669e521ef P e986ddf3938f4149b50fb75978f8378d: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/99b390d6452642a486239b8669e521ef/wal-000000031 (ops 151-155)
I20260812 06:17:01.389218 26588 log.cc:1079] T 99b390d6452642a486239b8669e521ef P e986ddf3938f4149b50fb75978f8378d: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/99b390d6452642a486239b8669e521ef/wal-000000032 (ops 156-160)
I20260812 06:17:01.389249 26588 log.cc:1079] T 99b390d6452642a486239b8669e521ef P e986ddf3938f4149b50fb75978f8378d: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/99b390d6452642a486239b8669e521ef/wal-000000033 (ops 161-164)
I20260812 06:17:01.389293 26588 log.cc:1079] T 99b390d6452642a486239b8669e521ef P e986ddf3938f4149b50fb75978f8378d: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/99b390d6452642a486239b8669e521ef/wal-000000034 (ops 165-169)
I20260812 06:17:01.389318 26588 log.cc:1079] T 99b390d6452642a486239b8669e521ef P e986ddf3938f4149b50fb75978f8378d: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/99b390d6452642a486239b8669e521ef/wal-000000035 (ops 170-174)
I20260812 06:17:01.389361 26588 log.cc:1079] T 99b390d6452642a486239b8669e521ef P e986ddf3938f4149b50fb75978f8378d: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/99b390d6452642a486239b8669e521ef/wal-000000036 (ops 175-179)
I20260812 06:17:01.389402 26588 log.cc:1079] T 99b390d6452642a486239b8669e521ef P e986ddf3938f4149b50fb75978f8378d: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/99b390d6452642a486239b8669e521ef/wal-000000037 (ops 180-184)
I20260812 06:17:01.389443 26588 log.cc:1079] T 99b390d6452642a486239b8669e521ef P e986ddf3938f4149b50fb75978f8378d: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/99b390d6452642a486239b8669e521ef/wal-000000038 (ops 185-188)
I20260812 06:17:01.420728 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: LogGCOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.032s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:17:01.421248 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef): perf score=3.181125
I20260812 06:17:01.439736 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.018s	user 0.008s	sys 0.005s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":5460,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:01.440393 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling UndoDeltaBlockGCOp(99b390d6452642a486239b8669e521ef): 493 bytes on disk
I20260812 06:17:01.440867 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: UndoDeltaBlockGCOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4}
I20260812 06:17:01.441395 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef): perf score=2.188937
I20260812 06:17:01.454468 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.013s	user 0.002s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4681,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:01.455061 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling MajorDeltaCompactionOp(99b390d6452642a486239b8669e521ef): perf score=1.000000
I20260812 06:17:01.711659 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: MajorDeltaCompactionOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.256s	user 0.184s	sys 0.071s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32938889,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":703,"lbm_read_time_us":17676,"lbm_reads_lt_1ms":775,"lbm_write_time_us":44215,"lbm_writes_lt_1ms":743,"mutex_wait_us":64,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":6400,"thread_start_us":101,"threads_started":1,"update_count":3500}
I20260812 06:17:01.712492 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef): perf score=14.095187
I20260812 06:17:01.736368 26474 heavy-update-compaction-itest.cc:229] Time spent updating: real 6.183s	user 2.197s	sys 0.192s
I20260812 06:17:01.761155 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.048s	user 0.023s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20904,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":3200,"update_count":2000}
I20260812 06:17:01.761997 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef): perf score=2.188937
I20260812 06:17:01.773836 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: FlushDeltaMemStoresOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4738,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:01.774420 26652 maintenance_manager.cc:419] P e986ddf3938f4149b50fb75978f8378d: Scheduling MajorDeltaCompactionOp(99b390d6452642a486239b8669e521ef): perf score=1.000000
I20260812 06:17:01.791119 26474 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.054s	user 0.005s	sys 0.000s
I20260812 06:17:01.792120 26474 tablet_server.cc:179] TabletServer@127.25.218.129:0 shutting down...
I20260812 06:17:01.938946 26588 maintenance_manager.cc:643] P e986ddf3938f4149b50fb75978f8378d: MajorDeltaCompactionOp(99b390d6452642a486239b8669e521ef) complete. Timing: real 0.164s	user 0.115s	sys 0.048s Metrics: {"cfile_cache_hit":30,"cfile_cache_hit_bytes":4221425,"cfile_cache_miss":502,"cfile_cache_miss_bytes":20512298,"cfile_init":4,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":981,"lbm_read_time_us":9022,"lbm_reads_lt_1ms":518,"lbm_write_time_us":29525,"lbm_writes_lt_1ms":543,"mutex_wait_us":89,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":19968,"update_count":2500}
I20260812 06:17:01.939953 26474 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:01.940378 26474 tablet_replica.cc:333] T 99b390d6452642a486239b8669e521ef P e986ddf3938f4149b50fb75978f8378d: stopping tablet replica
I20260812 06:17:01.940649 26474 raft_consensus.cc:2243] T 99b390d6452642a486239b8669e521ef P e986ddf3938f4149b50fb75978f8378d [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:01.940912 26474 raft_consensus.cc:2272] T 99b390d6452642a486239b8669e521ef P e986ddf3938f4149b50fb75978f8378d [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:01.958982 26474 tablet_server.cc:196] TabletServer@127.25.218.129:0 shutdown complete.
I20260812 06:17:01.990108 26474 master.cc:562] Master@127.25.218.190:46229 shutting down...
I20260812 06:17:01.994891 26474 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 27dc43753a084413b82a411b0b6f482e [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:01.995095 26474 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 27dc43753a084413b82a411b0b6f482e [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:01.995153 26474 tablet_replica.cc:333] T 00000000000000000000000000000000 P 27dc43753a084413b82a411b0b6f482e: stopping tablet replica
I20260812 06:17:02.008122 26474 master.cc:584] Master@127.25.218.190:46229 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (6878 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:17:02.100278 26474 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.25.218.190:45049
I20260812 06:17:02.100726 26474 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:02.105698 26689 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:02.105711 26687 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:02.105792 26686 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:02.105785 26474 server_base.cc:1061] running on GCE node
I20260812 06:17:02.106448 26474 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:02.106508 26474 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:02.106526 26474 hybrid_clock.cc:648] HybridClock initialized: now 1786515422106526 us; error 0 us; skew 500 ppm
I20260812 06:17:02.107785 26474 webserver.cc:533] Webserver started at http://127.25.218.190:46457/ using document root <none> and password file <none>
I20260812 06:17:02.107957 26474 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:02.108008 26474 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:02.108064 26474 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:02.108453 26474 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415209139-26474-0/minicluster-data/master-0-root/instance:
uuid: "f23944713bf2446282eef96305ec4672"
format_stamp: "Formatted at 2026-08-12 06:17:02 on dist-test-slave-csg5"
I20260812 06:17:02.110353 26474 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:02.112035 26694 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:02.112618 26474 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:02.112812 26474 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415209139-26474-0/minicluster-data/master-0-root
uuid: "f23944713bf2446282eef96305ec4672"
format_stamp: "Formatted at 2026-08-12 06:17:02 on dist-test-slave-csg5"
I20260812 06:17:02.112914 26474 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415209139-26474-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415209139-26474-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415209139-26474-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:02.121740 26474 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:02.122201 26474 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:02.127338 26474 rpc_server.cc:307] RPC server started. Bound to: 127.25.218.190:45049
I20260812 06:17:02.127487 26754 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.25.218.190:45049 every 8 connection(s)
I20260812 06:17:02.130983 26755 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:02.145511 26755 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P f23944713bf2446282eef96305ec4672: Bootstrap starting.
I20260812 06:17:02.146644 26755 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P f23944713bf2446282eef96305ec4672: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:02.148396 26755 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P f23944713bf2446282eef96305ec4672: No bootstrap required, opened a new log
I20260812 06:17:02.148881 26755 raft_consensus.cc:359] T 00000000000000000000000000000000 P f23944713bf2446282eef96305ec4672 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f23944713bf2446282eef96305ec4672" member_type: VOTER }
I20260812 06:17:02.148988 26755 raft_consensus.cc:385] T 00000000000000000000000000000000 P f23944713bf2446282eef96305ec4672 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:02.149012 26755 raft_consensus.cc:740] T 00000000000000000000000000000000 P f23944713bf2446282eef96305ec4672 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: f23944713bf2446282eef96305ec4672, State: Initialized, Role: FOLLOWER
I20260812 06:17:02.149215 26755 consensus_queue.cc:260] T 00000000000000000000000000000000 P f23944713bf2446282eef96305ec4672 [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: "f23944713bf2446282eef96305ec4672" member_type: VOTER }
I20260812 06:17:02.149327 26755 raft_consensus.cc:399] T 00000000000000000000000000000000 P f23944713bf2446282eef96305ec4672 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:02.149354 26755 raft_consensus.cc:493] T 00000000000000000000000000000000 P f23944713bf2446282eef96305ec4672 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:02.149385 26755 raft_consensus.cc:3060] T 00000000000000000000000000000000 P f23944713bf2446282eef96305ec4672 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:02.150381 26755 raft_consensus.cc:515] T 00000000000000000000000000000000 P f23944713bf2446282eef96305ec4672 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f23944713bf2446282eef96305ec4672" member_type: VOTER }
I20260812 06:17:02.150583 26755 leader_election.cc:304] T 00000000000000000000000000000000 P f23944713bf2446282eef96305ec4672 [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: f23944713bf2446282eef96305ec4672; no voters: 
I20260812 06:17:02.150892 26755 leader_election.cc:290] T 00000000000000000000000000000000 P f23944713bf2446282eef96305ec4672 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:02.151211 26758 raft_consensus.cc:2804] T 00000000000000000000000000000000 P f23944713bf2446282eef96305ec4672 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:02.151432 26758 raft_consensus.cc:697] T 00000000000000000000000000000000 P f23944713bf2446282eef96305ec4672 [term 1 LEADER]: Becoming Leader. State: Replica: f23944713bf2446282eef96305ec4672, State: Running, Role: LEADER
I20260812 06:17:02.151588 26758 consensus_queue.cc:237] T 00000000000000000000000000000000 P f23944713bf2446282eef96305ec4672 [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: "f23944713bf2446282eef96305ec4672" member_type: VOTER }
I20260812 06:17:02.152177 26759 sys_catalog.cc:455] T 00000000000000000000000000000000 P f23944713bf2446282eef96305ec4672 [sys.catalog]: SysCatalogTable state changed. Reason: New leader f23944713bf2446282eef96305ec4672. Latest consensus state: current_term: 1 leader_uuid: "f23944713bf2446282eef96305ec4672" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f23944713bf2446282eef96305ec4672" member_type: VOTER } }
I20260812 06:17:02.152205 26760 sys_catalog.cc:455] T 00000000000000000000000000000000 P f23944713bf2446282eef96305ec4672 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "f23944713bf2446282eef96305ec4672" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f23944713bf2446282eef96305ec4672" member_type: VOTER } }
I20260812 06:17:02.152295 26759 sys_catalog.cc:458] T 00000000000000000000000000000000 P f23944713bf2446282eef96305ec4672 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:02.153299 26755 sys_catalog.cc:565] T 00000000000000000000000000000000 P f23944713bf2446282eef96305ec4672 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:02.153422 26760 sys_catalog.cc:458] T 00000000000000000000000000000000 P f23944713bf2446282eef96305ec4672 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:02.153609 26764 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:02.154359 26764 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:02.155526 26474 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:02.156941 26764 catalog_manager.cc:1383] Generated new cluster ID: 24fa8ec10737476c95766e71b12ab97d
I20260812 06:17:02.157023 26764 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:02.168632 26764 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:02.169515 26764 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:02.174602 26764 catalog_manager.cc:6092] T 00000000000000000000000000000000 P f23944713bf2446282eef96305ec4672: Generated new TSK 0
I20260812 06:17:02.175017 26764 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:02.188539 26474 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:02.191761 26780 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:02.191728 26474 server_base.cc:1061] running on GCE node
W20260812 06:17:02.191700 26779 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:02.191728 26782 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:02.192243 26474 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:02.192296 26474 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:02.192317 26474 hybrid_clock.cc:648] HybridClock initialized: now 1786515422192317 us; error 0 us; skew 500 ppm
I20260812 06:17:02.193466 26474 webserver.cc:533] Webserver started at http://127.25.218.129:38943/ using document root <none> and password file <none>
I20260812 06:17:02.193624 26474 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:02.193670 26474 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:02.193737 26474 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:02.194175 26474 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415209139-26474-0/minicluster-data/ts-0-root/instance:
uuid: "cab28ff2fc704213a596d59a51cbe098"
format_stamp: "Formatted at 2026-08-12 06:17:02 on dist-test-slave-csg5"
I20260812 06:17:02.196080 26474 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:17:02.198410 26788 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:02.199258 26474 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:17:02.199460 26474 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415209139-26474-0/minicluster-data/ts-0-root
uuid: "cab28ff2fc704213a596d59a51cbe098"
format_stamp: "Formatted at 2026-08-12 06:17:02 on dist-test-slave-csg5"
I20260812 06:17:02.199579 26474 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415209139-26474-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415209139-26474-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415209139-26474-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:02.218289 26474 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:02.218938 26474 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:02.219321 26474 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:02.219863 26474 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:02.219938 26474 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:02.219992 26474 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:02.220047 26474 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:02.229532 26474 rpc_server.cc:307] RPC server started. Bound to: 127.25.218.129:35607
I20260812 06:17:02.229736 26861 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.25.218.129:35607 every 8 connection(s)
I20260812 06:17:02.242951 26862 heartbeater.cc:344] Connected to a master server at 127.25.218.190:45049
I20260812 06:17:02.243152 26862 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:02.243537 26862 heartbeater.cc:507] Master 127.25.218.190:45049 requested a full tablet report, sending...
I20260812 06:17:02.244508 26712 ts_manager.cc:194] Registered new tserver with Master: cab28ff2fc704213a596d59a51cbe098 (127.25.218.129:35607)
I20260812 06:17:02.245309 26474 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.015214002s
I20260812 06:17:02.245476 26712 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:33440
I20260812 06:17:02.261150 26712 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:33454:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:17:02.276947 26815 tablet_service.cc:1511] Processing CreateTablet for tablet 531c6529b8d64d46a54b34e30e43af2e (DEFAULT_TABLE table=heavy-update-compaction-test [id=699187b20ae24464bf99c67caa5c8979]), partition=
I20260812 06:17:02.277431 26815 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 531c6529b8d64d46a54b34e30e43af2e. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:02.280181 26875 tablet_bootstrap.cc:492] T 531c6529b8d64d46a54b34e30e43af2e P cab28ff2fc704213a596d59a51cbe098: Bootstrap starting.
I20260812 06:17:02.281451 26875 tablet_bootstrap.cc:654] T 531c6529b8d64d46a54b34e30e43af2e P cab28ff2fc704213a596d59a51cbe098: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:02.282905 26875 tablet_bootstrap.cc:492] T 531c6529b8d64d46a54b34e30e43af2e P cab28ff2fc704213a596d59a51cbe098: No bootstrap required, opened a new log
I20260812 06:17:02.283032 26875 ts_tablet_manager.cc:1403] T 531c6529b8d64d46a54b34e30e43af2e P cab28ff2fc704213a596d59a51cbe098: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:17:02.283496 26875 raft_consensus.cc:359] T 531c6529b8d64d46a54b34e30e43af2e P cab28ff2fc704213a596d59a51cbe098 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "cab28ff2fc704213a596d59a51cbe098" member_type: VOTER last_known_addr { host: "127.25.218.129" port: 35607 } }
I20260812 06:17:02.283599 26875 raft_consensus.cc:385] T 531c6529b8d64d46a54b34e30e43af2e P cab28ff2fc704213a596d59a51cbe098 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:02.283622 26875 raft_consensus.cc:740] T 531c6529b8d64d46a54b34e30e43af2e P cab28ff2fc704213a596d59a51cbe098 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: cab28ff2fc704213a596d59a51cbe098, State: Initialized, Role: FOLLOWER
I20260812 06:17:02.283802 26875 consensus_queue.cc:260] T 531c6529b8d64d46a54b34e30e43af2e P cab28ff2fc704213a596d59a51cbe098 [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: "cab28ff2fc704213a596d59a51cbe098" member_type: VOTER last_known_addr { host: "127.25.218.129" port: 35607 } }
I20260812 06:17:02.283881 26875 raft_consensus.cc:399] T 531c6529b8d64d46a54b34e30e43af2e P cab28ff2fc704213a596d59a51cbe098 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:02.283905 26875 raft_consensus.cc:493] T 531c6529b8d64d46a54b34e30e43af2e P cab28ff2fc704213a596d59a51cbe098 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:02.283934 26875 raft_consensus.cc:3060] T 531c6529b8d64d46a54b34e30e43af2e P cab28ff2fc704213a596d59a51cbe098 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:02.284698 26875 raft_consensus.cc:515] T 531c6529b8d64d46a54b34e30e43af2e P cab28ff2fc704213a596d59a51cbe098 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "cab28ff2fc704213a596d59a51cbe098" member_type: VOTER last_known_addr { host: "127.25.218.129" port: 35607 } }
I20260812 06:17:02.284837 26875 leader_election.cc:304] T 531c6529b8d64d46a54b34e30e43af2e P cab28ff2fc704213a596d59a51cbe098 [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: cab28ff2fc704213a596d59a51cbe098; no voters: 
I20260812 06:17:02.285006 26875 leader_election.cc:290] T 531c6529b8d64d46a54b34e30e43af2e P cab28ff2fc704213a596d59a51cbe098 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:02.285298 26877 raft_consensus.cc:2804] T 531c6529b8d64d46a54b34e30e43af2e P cab28ff2fc704213a596d59a51cbe098 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:02.285383 26875 ts_tablet_manager.cc:1434] T 531c6529b8d64d46a54b34e30e43af2e P cab28ff2fc704213a596d59a51cbe098: Time spent starting tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:02.285444 26862 heartbeater.cc:499] Master 127.25.218.190:45049 was elected leader, sending a full tablet report...
I20260812 06:17:02.285583 26877 raft_consensus.cc:697] T 531c6529b8d64d46a54b34e30e43af2e P cab28ff2fc704213a596d59a51cbe098 [term 1 LEADER]: Becoming Leader. State: Replica: cab28ff2fc704213a596d59a51cbe098, State: Running, Role: LEADER
I20260812 06:17:02.285768 26877 consensus_queue.cc:237] T 531c6529b8d64d46a54b34e30e43af2e P cab28ff2fc704213a596d59a51cbe098 [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: "cab28ff2fc704213a596d59a51cbe098" member_type: VOTER last_known_addr { host: "127.25.218.129" port: 35607 } }
I20260812 06:17:02.287561 26712 catalog_manager.cc:5719] T 531c6529b8d64d46a54b34e30e43af2e P cab28ff2fc704213a596d59a51cbe098 reported cstate change: term changed from 0 to 1, leader changed from <none> to cab28ff2fc704213a596d59a51cbe098 (127.25.218.129). New cstate: current_term: 1 leader_uuid: "cab28ff2fc704213a596d59a51cbe098" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "cab28ff2fc704213a596d59a51cbe098" member_type: VOTER last_known_addr { host: "127.25.218.129" port: 35607 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:02.360948 26474 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.065s	user 0.018s	sys 0.008s
I20260812 06:17:02.480732 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling FlushMRSOp(531c6529b8d64d46a54b34e30e43af2e): perf score=15.086190
I20260812 06:17:02.609014 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: FlushMRSOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.128s	user 0.100s	sys 0.024s Metrics: {"bytes_written":8328151,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":99,"dirs.run_cpu_time_us":203,"dirs.run_wall_time_us":1062,"drs_written":1,"lbm_read_time_us":108,"lbm_reads_lt_1ms":4,"lbm_write_time_us":30486,"lbm_writes_lt_1ms":560,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"spinlock_wait_cycles":14720,"update_count":1015}
I20260812 06:17:02.609827 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling LogGCOp(531c6529b8d64d46a54b34e30e43af2e): free 11976772 bytes of WAL
I20260812 06:17:02.610157 26793 log_reader.cc:385] T 531c6529b8d64d46a54b34e30e43af2e: removed 1 log segments from log reader
I20260812 06:17:02.610256 26793 log.cc:1079] T 531c6529b8d64d46a54b34e30e43af2e P cab28ff2fc704213a596d59a51cbe098: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/531c6529b8d64d46a54b34e30e43af2e/wal-000000001 (ops 1-6)
I20260812 06:17:02.613097 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: LogGCOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:17:02.613514 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling UndoDeltaBlockGCOp(531c6529b8d64d46a54b34e30e43af2e): 12308958 bytes on disk
I20260812 06:17:02.614063 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: UndoDeltaBlockGCOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":68,"lbm_reads_lt_1ms":4}
I20260812 06:17:02.614542 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e): perf score=2.188937
I20260812 06:17:02.635155 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.020s	user 0.008s	sys 0.008s Metrics: {"bytes_written":3979584,"delete_count":0,"lbm_write_time_us":6209,"lbm_writes_lt_1ms":100,"reinsert_count":0,"update_count":485}
I20260812 06:17:02.635735 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling MajorDeltaCompactionOp(531c6529b8d64d46a54b34e30e43af2e): perf score=1.000000
I20260812 06:17:02.753300 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: MajorDeltaCompactionOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.117s	user 0.090s	sys 0.027s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16528898,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":725,"lbm_read_time_us":7628,"lbm_reads_lt_1ms":360,"lbm_write_time_us":20803,"lbm_writes_lt_1ms":343,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":2048,"thread_start_us":361,"threads_started":5,"update_count":1500}
I20260812 06:17:02.754053 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e): perf score=10.126437
I20260812 06:17:02.806013 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.052s	user 0.018s	sys 0.020s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17868,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:02.806517 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e): perf score=2.188937
I20260812 06:17:02.818037 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4237,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:02.819067 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling MajorDeltaCompactionOp(531c6529b8d64d46a54b34e30e43af2e): perf score=1.000000
I20260812 06:17:02.956966 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: MajorDeltaCompactionOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.138s	user 0.101s	sys 0.037s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":421,"lbm_read_time_us":10515,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23789,"lbm_writes_lt_1ms":443,"mutex_wait_us":101,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11648,"update_count":2000}
I20260812 06:17:02.957490 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e): perf score=10.126437
I20260812 06:17:03.010046 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.052s	user 0.011s	sys 0.036s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18342,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:03.010962 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e): perf score=2.188937
I20260812 06:17:03.022301 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4299,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:03.022894 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling MajorDeltaCompactionOp(531c6529b8d64d46a54b34e30e43af2e): perf score=1.000000
I20260812 06:17:03.184278 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: MajorDeltaCompactionOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.161s	user 0.099s	sys 0.060s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":167,"lbm_read_time_us":11323,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22780,"lbm_writes_lt_1ms":443,"mutex_wait_us":22,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":54400,"update_count":2000}
I20260812 06:17:03.185038 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e): perf score=10.126437
I20260812 06:17:03.236749 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.052s	user 0.033s	sys 0.003s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16118,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:03.237419 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e): perf score=2.188937
I20260812 06:17:03.254031 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.016s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6058,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:03.254999 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling MajorDeltaCompactionOp(531c6529b8d64d46a54b34e30e43af2e): perf score=1.000000
I20260812 06:17:03.392820 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: MajorDeltaCompactionOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.137s	user 0.108s	sys 0.029s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":717,"lbm_read_time_us":8516,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27496,"lbm_writes_lt_1ms":443,"mutex_wait_us":49,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8576,"update_count":2000}
I20260812 06:17:03.393765 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e): perf score=10.126437
I20260812 06:17:03.446704 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.053s	user 0.023s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19994,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:03.447299 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e): perf score=2.188937
I20260812 06:17:03.462080 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5819,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:03.462882 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling MajorDeltaCompactionOp(531c6529b8d64d46a54b34e30e43af2e): perf score=1.000000
I20260812 06:17:03.609462 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: MajorDeltaCompactionOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.146s	user 0.099s	sys 0.045s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":344,"lbm_read_time_us":9233,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28296,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:03.610132 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e): perf score=10.126437
I20260812 06:17:03.656407 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.046s	user 0.029s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14803,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:03.657156 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e): perf score=2.188937
I20260812 06:17:03.669265 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.012s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4846,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:03.669780 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling MajorDeltaCompactionOp(531c6529b8d64d46a54b34e30e43af2e): perf score=1.000000
I20260812 06:17:03.825695 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: MajorDeltaCompactionOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.156s	user 0.120s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":661,"lbm_read_time_us":11561,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23618,"lbm_writes_lt_1ms":443,"mutex_wait_us":83,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13952,"update_count":2000}
I20260812 06:17:03.826325 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e): perf score=10.126437
I20260812 06:17:03.872773 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.046s	user 0.032s	sys 0.005s Metrics: {"bytes_written":12307495,"delete_count":0,"lbm_write_time_us":16967,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:03.873386 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e): perf score=2.188937
I20260812 06:17:03.886811 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.013s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4535,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:03.887444 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling MajorDeltaCompactionOp(531c6529b8d64d46a54b34e30e43af2e): perf score=1.000000
I20260812 06:17:04.036432 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: MajorDeltaCompactionOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.149s	user 0.124s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631317,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":155,"lbm_read_time_us":9929,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29995,"lbm_writes_lt_1ms":443,"mutex_wait_us":46,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11520,"update_count":2000}
I20260812 06:17:04.037640 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e): perf score=10.126437
I20260812 06:17:04.077947 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.040s	user 0.023s	sys 0.013s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16877,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":2944,"update_count":1500}
I20260812 06:17:04.078977 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e): perf score=2.188937
I20260812 06:17:04.108404 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.029s	user 0.002s	sys 0.013s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6608,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":4736,"update_count":500}
I20260812 06:17:04.109021 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e): perf score=2.188937
I20260812 06:17:04.120395 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4207,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:04.121121 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling FlushMRSOp(531c6529b8d64d46a54b34e30e43af2e): perf score=1.000000
I20260812 06:17:04.155022 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: FlushMRSOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.034s	user 0.033s	sys 0.000s Metrics: {"bytes_written":1316414,"cfile_init":1,"dirs.queue_time_us":68,"dirs.run_cpu_time_us":349,"dirs.run_wall_time_us":1972,"drs_written":1,"lbm_read_time_us":71,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2317,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:17:04.155889 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling LogGCOp(531c6529b8d64d46a54b34e30e43af2e): free 129773557 bytes of WAL
I20260812 06:17:04.156164 26793 log_reader.cc:385] T 531c6529b8d64d46a54b34e30e43af2e: removed 13 log segments from log reader
I20260812 06:17:04.156243 26793 log.cc:1079] T 531c6529b8d64d46a54b34e30e43af2e P cab28ff2fc704213a596d59a51cbe098: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/531c6529b8d64d46a54b34e30e43af2e/wal-000000002 (ops 7-11)
I20260812 06:17:04.156304 26793 log.cc:1079] T 531c6529b8d64d46a54b34e30e43af2e P cab28ff2fc704213a596d59a51cbe098: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/531c6529b8d64d46a54b34e30e43af2e/wal-000000003 (ops 12-16)
I20260812 06:17:04.156447 26793 log.cc:1079] T 531c6529b8d64d46a54b34e30e43af2e P cab28ff2fc704213a596d59a51cbe098: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/531c6529b8d64d46a54b34e30e43af2e/wal-000000004 (ops 17-21)
I20260812 06:17:04.156497 26793 log.cc:1079] T 531c6529b8d64d46a54b34e30e43af2e P cab28ff2fc704213a596d59a51cbe098: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/531c6529b8d64d46a54b34e30e43af2e/wal-000000005 (ops 22-26)
I20260812 06:17:04.156538 26793 log.cc:1079] T 531c6529b8d64d46a54b34e30e43af2e P cab28ff2fc704213a596d59a51cbe098: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/531c6529b8d64d46a54b34e30e43af2e/wal-000000006 (ops 27-31)
I20260812 06:17:04.156579 26793 log.cc:1079] T 531c6529b8d64d46a54b34e30e43af2e P cab28ff2fc704213a596d59a51cbe098: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/531c6529b8d64d46a54b34e30e43af2e/wal-000000007 (ops 32-36)
I20260812 06:17:04.156625 26793 log.cc:1079] T 531c6529b8d64d46a54b34e30e43af2e P cab28ff2fc704213a596d59a51cbe098: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/531c6529b8d64d46a54b34e30e43af2e/wal-000000008 (ops 37-40)
I20260812 06:17:04.156670 26793 log.cc:1079] T 531c6529b8d64d46a54b34e30e43af2e P cab28ff2fc704213a596d59a51cbe098: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/531c6529b8d64d46a54b34e30e43af2e/wal-000000009 (ops 41-45)
I20260812 06:17:04.156713 26793 log.cc:1079] T 531c6529b8d64d46a54b34e30e43af2e P cab28ff2fc704213a596d59a51cbe098: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/531c6529b8d64d46a54b34e30e43af2e/wal-000000010 (ops 46-50)
I20260812 06:17:04.156757 26793 log.cc:1079] T 531c6529b8d64d46a54b34e30e43af2e P cab28ff2fc704213a596d59a51cbe098: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/531c6529b8d64d46a54b34e30e43af2e/wal-000000011 (ops 51-55)
I20260812 06:17:04.156810 26793 log.cc:1079] T 531c6529b8d64d46a54b34e30e43af2e P cab28ff2fc704213a596d59a51cbe098: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/531c6529b8d64d46a54b34e30e43af2e/wal-000000012 (ops 56-60)
I20260812 06:17:04.156852 26793 log.cc:1079] T 531c6529b8d64d46a54b34e30e43af2e P cab28ff2fc704213a596d59a51cbe098: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/531c6529b8d64d46a54b34e30e43af2e/wal-000000013 (ops 61-65)
I20260812 06:17:04.156898 26793 log.cc:1079] T 531c6529b8d64d46a54b34e30e43af2e P cab28ff2fc704213a596d59a51cbe098: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/531c6529b8d64d46a54b34e30e43af2e/wal-000000014 (ops 66-70)
I20260812 06:17:04.185760 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: LogGCOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.030s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:17:04.186437 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling UndoDeltaBlockGCOp(531c6529b8d64d46a54b34e30e43af2e): 492 bytes on disk
I20260812 06:17:04.187006 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: UndoDeltaBlockGCOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":87,"lbm_reads_lt_1ms":4}
I20260812 06:17:04.187676 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e): perf score=4.173312
I20260812 06:17:04.208765 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.021s	user 0.015s	sys 0.004s Metrics: {"bytes_written":5866705,"delete_count":0,"lbm_write_time_us":8778,"lbm_writes_lt_1ms":146,"reinsert_count":0,"update_count":715}
I20260812 06:17:04.209435 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e): perf score=1.196750
I20260812 06:17:04.219476 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":2338579,"delete_count":0,"lbm_write_time_us":3056,"lbm_writes_lt_1ms":60,"reinsert_count":0,"update_count":285}
I20260812 06:17:04.219995 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling MajorDeltaCompactionOp(531c6529b8d64d46a54b34e30e43af2e): perf score=1.000000
I20260812 06:17:04.435544 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: MajorDeltaCompactionOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.215s	user 0.158s	sys 0.056s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32938866,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":67,"lbm_read_time_us":15556,"lbm_reads_lt_1ms":775,"lbm_write_time_us":41434,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":7040,"thread_start_us":104,"threads_started":1,"update_count":3500}
I20260812 06:17:04.436741 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e): perf score=14.095187
I20260812 06:17:04.496560 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.058s	user 0.037s	sys 0.019s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":25750,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:04.497231 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e): perf score=2.188937
I20260812 06:17:04.521167 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.024s	user 0.009s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5957,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:04.522001 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling MajorDeltaCompactionOp(531c6529b8d64d46a54b34e30e43af2e): perf score=1.000000
I20260812 06:17:04.721167 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: MajorDeltaCompactionOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.199s	user 0.131s	sys 0.068s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733725,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":247,"lbm_read_time_us":12419,"lbm_reads_lt_1ms":564,"lbm_write_time_us":32834,"lbm_writes_lt_1ms":543,"mutex_wait_us":65,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2500}
I20260812 06:17:04.722033 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e): perf score=14.095187
I20260812 06:17:04.780925 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.059s	user 0.028s	sys 0.028s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":28360,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":400,"reinsert_count":0,"update_count":2000}
I20260812 06:17:04.781570 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e): perf score=3.181125
I20260812 06:17:04.805225 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.023s	user 0.011s	sys 0.003s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":6150,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:04.805716 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e): perf score=2.188937
I20260812 06:17:04.831238 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.025s	user 0.013s	sys 0.012s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5931,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:04.831799 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling MajorDeltaCompactionOp(531c6529b8d64d46a54b34e30e43af2e): perf score=1.000000
I20260812 06:17:05.042965 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: MajorDeltaCompactionOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.211s	user 0.155s	sys 0.056s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28836244,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":159,"lbm_read_time_us":14488,"lbm_reads_lt_1ms":673,"lbm_write_time_us":34377,"lbm_writes_lt_1ms":643,"mutex_wait_us":37,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":7424,"update_count":3000}
I20260812 06:17:05.043663 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e): perf score=14.095187
I20260812 06:17:05.113768 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.070s	user 0.037s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23567,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:05.114558 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e): perf score=2.188937
I20260812 06:17:05.126739 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.012s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4618,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:05.127321 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling MajorDeltaCompactionOp(531c6529b8d64d46a54b34e30e43af2e): perf score=1.000000
I20260812 06:17:05.332458 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: MajorDeltaCompactionOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.205s	user 0.151s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733722,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":176,"lbm_read_time_us":13375,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34410,"lbm_writes_lt_1ms":543,"mutex_wait_us":1,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:05.333249 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e): perf score=10.126437
I20260812 06:17:05.375874 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.042s	user 0.022s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18013,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:05.376627 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e): perf score=2.188937
I20260812 06:17:05.393332 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.016s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6465,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:05.394134 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling MajorDeltaCompactionOp(531c6529b8d64d46a54b34e30e43af2e): perf score=1.000000
I20260812 06:17:05.530822 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: MajorDeltaCompactionOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.136s	user 0.104s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":678,"lbm_read_time_us":8981,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24771,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6528,"update_count":2000}
I20260812 06:17:05.531594 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e): perf score=10.126437
I20260812 06:17:05.573107 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.041s	user 0.021s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17080,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:05.573738 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e): perf score=2.188937
I20260812 06:17:05.584826 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4322,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:05.585485 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling MajorDeltaCompactionOp(531c6529b8d64d46a54b34e30e43af2e): perf score=1.000000
I20260812 06:17:05.723395 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: MajorDeltaCompactionOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.138s	user 0.097s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1363,"lbm_read_time_us":9534,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26541,"lbm_writes_lt_1ms":443,"mutex_wait_us":357,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12160,"update_count":2000}
I20260812 06:17:05.724054 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e): perf score=10.126437
I20260812 06:17:05.764118 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.040s	user 0.023s	sys 0.012s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15516,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:05.764770 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling FlushMRSOp(531c6529b8d64d46a54b34e30e43af2e): perf score=1.000000
I20260812 06:17:05.819664 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: FlushMRSOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.055s	user 0.031s	sys 0.005s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":62,"dirs.run_cpu_time_us":207,"dirs.run_wall_time_us":1443,"drs_written":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1795,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:17:05.820488 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling LogGCOp(531c6529b8d64d46a54b34e30e43af2e): free 120553389 bytes of WAL
I20260812 06:17:05.820868 26793 log_reader.cc:385] T 531c6529b8d64d46a54b34e30e43af2e: removed 12 log segments from log reader
I20260812 06:17:05.820956 26793 log.cc:1079] T 531c6529b8d64d46a54b34e30e43af2e P cab28ff2fc704213a596d59a51cbe098: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/531c6529b8d64d46a54b34e30e43af2e/wal-000000015 (ops 71-75)
I20260812 06:17:05.821010 26793 log.cc:1079] T 531c6529b8d64d46a54b34e30e43af2e P cab28ff2fc704213a596d59a51cbe098: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/531c6529b8d64d46a54b34e30e43af2e/wal-000000016 (ops 76-80)
I20260812 06:17:05.821067 26793 log.cc:1079] T 531c6529b8d64d46a54b34e30e43af2e P cab28ff2fc704213a596d59a51cbe098: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/531c6529b8d64d46a54b34e30e43af2e/wal-000000017 (ops 81-85)
I20260812 06:17:05.821107 26793 log.cc:1079] T 531c6529b8d64d46a54b34e30e43af2e P cab28ff2fc704213a596d59a51cbe098: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/531c6529b8d64d46a54b34e30e43af2e/wal-000000018 (ops 86-90)
I20260812 06:17:05.821132 26793 log.cc:1079] T 531c6529b8d64d46a54b34e30e43af2e P cab28ff2fc704213a596d59a51cbe098: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/531c6529b8d64d46a54b34e30e43af2e/wal-000000019 (ops 91-94)
I20260812 06:17:05.821156 26793 log.cc:1079] T 531c6529b8d64d46a54b34e30e43af2e P cab28ff2fc704213a596d59a51cbe098: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/531c6529b8d64d46a54b34e30e43af2e/wal-000000020 (ops 95-99)
I20260812 06:17:05.821178 26793 log.cc:1079] T 531c6529b8d64d46a54b34e30e43af2e P cab28ff2fc704213a596d59a51cbe098: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/531c6529b8d64d46a54b34e30e43af2e/wal-000000021 (ops 100-104)
I20260812 06:17:05.821202 26793 log.cc:1079] T 531c6529b8d64d46a54b34e30e43af2e P cab28ff2fc704213a596d59a51cbe098: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/531c6529b8d64d46a54b34e30e43af2e/wal-000000022 (ops 105-108)
I20260812 06:17:05.821231 26793 log.cc:1079] T 531c6529b8d64d46a54b34e30e43af2e P cab28ff2fc704213a596d59a51cbe098: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/531c6529b8d64d46a54b34e30e43af2e/wal-000000023 (ops 109-113)
I20260812 06:17:05.821267 26793 log.cc:1079] T 531c6529b8d64d46a54b34e30e43af2e P cab28ff2fc704213a596d59a51cbe098: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/531c6529b8d64d46a54b34e30e43af2e/wal-000000024 (ops 114-118)
I20260812 06:17:05.821305 26793 log.cc:1079] T 531c6529b8d64d46a54b34e30e43af2e P cab28ff2fc704213a596d59a51cbe098: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/531c6529b8d64d46a54b34e30e43af2e/wal-000000025 (ops 119-123)
I20260812 06:17:05.821345 26793 log.cc:1079] T 531c6529b8d64d46a54b34e30e43af2e P cab28ff2fc704213a596d59a51cbe098: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/531c6529b8d64d46a54b34e30e43af2e/wal-000000026 (ops 124-128)
I20260812 06:17:05.846549 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: LogGCOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.026s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:17:05.847195 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e): perf score=6.157687
I20260812 06:17:05.877022 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.030s	user 0.014s	sys 0.013s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":13069,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:17:05.877575 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling LogGCOp(531c6529b8d64d46a54b34e30e43af2e): free 12017947 bytes of WAL
I20260812 06:17:05.877806 26793 log_reader.cc:385] T 531c6529b8d64d46a54b34e30e43af2e: removed 1 log segments from log reader
I20260812 06:17:05.877887 26793 log.cc:1079] T 531c6529b8d64d46a54b34e30e43af2e P cab28ff2fc704213a596d59a51cbe098: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/531c6529b8d64d46a54b34e30e43af2e/wal-000000027 (ops 129-133)
I20260812 06:17:05.881129 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: LogGCOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:17:05.881659 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling UndoDeltaBlockGCOp(531c6529b8d64d46a54b34e30e43af2e): 473 bytes on disk
I20260812 06:17:05.882263 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: UndoDeltaBlockGCOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":94,"lbm_reads_lt_1ms":4}
I20260812 06:17:05.882958 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e): perf score=2.188937
I20260812 06:17:05.900722 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.018s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6798,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:05.901394 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling MajorDeltaCompactionOp(531c6529b8d64d46a54b34e30e43af2e): perf score=1.000000
I20260812 06:17:06.101868 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: MajorDeltaCompactionOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.200s	user 0.138s	sys 0.055s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28836255,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":491,"lbm_read_time_us":13612,"lbm_reads_lt_1ms":665,"lbm_write_time_us":41882,"lbm_writes_lt_1ms":643,"mutex_wait_us":46,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":8576,"thread_start_us":84,"threads_started":1,"update_count":3000}
I20260812 06:17:06.102746 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e): perf score=14.095187
I20260812 06:17:06.162322 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.059s	user 0.027s	sys 0.027s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":27407,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:17:06.162949 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e): perf score=2.188937
I20260812 06:17:06.176971 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.014s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5036,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:06.177564 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling MajorDeltaCompactionOp(531c6529b8d64d46a54b34e30e43af2e): perf score=1.000000
I20260812 06:17:06.366150 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: MajorDeltaCompactionOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.188s	user 0.144s	sys 0.025s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":248,"lbm_read_time_us":12366,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34872,"lbm_writes_lt_1ms":543,"mutex_wait_us":61,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":16512,"update_count":2500}
I20260812 06:17:06.366911 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e): perf score=14.095187
I20260812 06:17:06.434070 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.067s	user 0.029s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21744,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:06.434846 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e): perf score=2.188937
I20260812 06:17:06.447685 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.013s	user 0.002s	sys 0.010s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4600,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:06.448428 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling MajorDeltaCompactionOp(531c6529b8d64d46a54b34e30e43af2e): perf score=1.000000
I20260812 06:17:06.644359 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: MajorDeltaCompactionOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.196s	user 0.146s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":861,"lbm_read_time_us":13966,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32067,"lbm_writes_lt_1ms":543,"mutex_wait_us":353,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":34176,"update_count":2500}
I20260812 06:17:06.645032 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e): perf score=14.095187
I20260812 06:17:06.725035 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.080s	user 0.032s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":34924,"lbm_writes_10-100_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:06.725672 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e): perf score=2.188937
I20260812 06:17:06.736310 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.010s	user 0.005s	sys 0.004s 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:17:06.736846 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling MajorDeltaCompactionOp(531c6529b8d64d46a54b34e30e43af2e): perf score=1.000000
I20260812 06:17:06.928815 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: MajorDeltaCompactionOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.192s	user 0.135s	sys 0.047s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":226,"lbm_read_time_us":12949,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33910,"lbm_writes_lt_1ms":543,"mutex_wait_us":36,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":16000,"update_count":2500}
I20260812 06:17:06.929546 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e): perf score=14.095187
I20260812 06:17:07.001242 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.071s	user 0.036s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25442,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:07.001878 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e): perf score=2.188937
I20260812 06:17:07.013386 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4553,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:07.013899 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling MajorDeltaCompactionOp(531c6529b8d64d46a54b34e30e43af2e): perf score=1.000000
I20260812 06:17:07.185942 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: MajorDeltaCompactionOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.172s	user 0.097s	sys 0.073s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1888,"lbm_read_time_us":13727,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27057,"lbm_writes_lt_1ms":543,"mutex_wait_us":295,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4992,"update_count":2500}
I20260812 06:17:07.187281 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e): perf score=11.118625
I20260812 06:17:07.230845 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.043s	user 0.027s	sys 0.016s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":17461,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:07.232334 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e): perf score=2.188937
I20260812 06:17:07.250864 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.018s	user 0.010s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6935,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:07.251580 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling MajorDeltaCompactionOp(531c6529b8d64d46a54b34e30e43af2e): perf score=1.000000
I20260812 06:17:07.421594 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: MajorDeltaCompactionOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.170s	user 0.117s	sys 0.044s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631303,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1254,"lbm_read_time_us":9968,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26245,"lbm_writes_lt_1ms":443,"mutex_wait_us":339,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:07.422716 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e): perf score=11.118625
I20260812 06:17:07.460958 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.038s	user 0.023s	sys 0.012s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15458,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:07.461844 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e): perf score=2.188937
I20260812 06:17:07.483986 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.022s	user 0.004s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4990,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:07.484524 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e): perf score=2.188937
I20260812 06:17:07.496086 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4403,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:07.496629 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling FlushMRSOp(531c6529b8d64d46a54b34e30e43af2e): perf score=1.000000
I20260812 06:17:07.530143 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: FlushMRSOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.033s	user 0.028s	sys 0.003s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":82,"dirs.run_cpu_time_us":252,"dirs.run_wall_time_us":1778,"drs_written":1,"lbm_read_time_us":67,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1702,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:07.530968 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling LogGCOp(531c6529b8d64d46a54b34e30e43af2e): free 120553636 bytes of WAL
I20260812 06:17:07.531240 26793 log_reader.cc:385] T 531c6529b8d64d46a54b34e30e43af2e: removed 12 log segments from log reader
I20260812 06:17:07.531314 26793 log.cc:1079] T 531c6529b8d64d46a54b34e30e43af2e P cab28ff2fc704213a596d59a51cbe098: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/531c6529b8d64d46a54b34e30e43af2e/wal-000000028 (ops 134-138)
I20260812 06:17:07.531358 26793 log.cc:1079] T 531c6529b8d64d46a54b34e30e43af2e P cab28ff2fc704213a596d59a51cbe098: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/531c6529b8d64d46a54b34e30e43af2e/wal-000000029 (ops 139-142)
I20260812 06:17:07.531390 26793 log.cc:1079] T 531c6529b8d64d46a54b34e30e43af2e P cab28ff2fc704213a596d59a51cbe098: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/531c6529b8d64d46a54b34e30e43af2e/wal-000000030 (ops 143-147)
I20260812 06:17:07.531419 26793 log.cc:1079] T 531c6529b8d64d46a54b34e30e43af2e P cab28ff2fc704213a596d59a51cbe098: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/531c6529b8d64d46a54b34e30e43af2e/wal-000000031 (ops 148-152)
I20260812 06:17:07.531451 26793 log.cc:1079] T 531c6529b8d64d46a54b34e30e43af2e P cab28ff2fc704213a596d59a51cbe098: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/531c6529b8d64d46a54b34e30e43af2e/wal-000000032 (ops 153-156)
I20260812 06:17:07.531487 26793 log.cc:1079] T 531c6529b8d64d46a54b34e30e43af2e P cab28ff2fc704213a596d59a51cbe098: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/531c6529b8d64d46a54b34e30e43af2e/wal-000000033 (ops 157-161)
I20260812 06:17:07.531518 26793 log.cc:1079] T 531c6529b8d64d46a54b34e30e43af2e P cab28ff2fc704213a596d59a51cbe098: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/531c6529b8d64d46a54b34e30e43af2e/wal-000000034 (ops 162-166)
I20260812 06:17:07.531548 26793 log.cc:1079] T 531c6529b8d64d46a54b34e30e43af2e P cab28ff2fc704213a596d59a51cbe098: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/531c6529b8d64d46a54b34e30e43af2e/wal-000000035 (ops 167-171)
I20260812 06:17:07.531577 26793 log.cc:1079] T 531c6529b8d64d46a54b34e30e43af2e P cab28ff2fc704213a596d59a51cbe098: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/531c6529b8d64d46a54b34e30e43af2e/wal-000000036 (ops 172-176)
I20260812 06:17:07.531607 26793 log.cc:1079] T 531c6529b8d64d46a54b34e30e43af2e P cab28ff2fc704213a596d59a51cbe098: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/531c6529b8d64d46a54b34e30e43af2e/wal-000000037 (ops 177-181)
I20260812 06:17:07.531641 26793 log.cc:1079] T 531c6529b8d64d46a54b34e30e43af2e P cab28ff2fc704213a596d59a51cbe098: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/531c6529b8d64d46a54b34e30e43af2e/wal-000000038 (ops 182-186)
I20260812 06:17:07.531674 26793 log.cc:1079] T 531c6529b8d64d46a54b34e30e43af2e P cab28ff2fc704213a596d59a51cbe098: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/531c6529b8d64d46a54b34e30e43af2e/wal-000000039 (ops 187-191)
I20260812 06:17:07.560248 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: LogGCOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.029s	user 0.000s	sys 0.028s Metrics: {}
I20260812 06:17:07.560874 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling UndoDeltaBlockGCOp(531c6529b8d64d46a54b34e30e43af2e): 483 bytes on disk
I20260812 06:17:07.561532 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: UndoDeltaBlockGCOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":76,"lbm_reads_lt_1ms":4}
I20260812 06:17:07.562619 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e): perf score=2.188937
I20260812 06:17:07.585954 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.023s	user 0.008s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5199,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:07.587311 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling LogGCOp(531c6529b8d64d46a54b34e30e43af2e): free 12017954 bytes of WAL
I20260812 06:17:07.587617 26793 log_reader.cc:385] T 531c6529b8d64d46a54b34e30e43af2e: removed 1 log segments from log reader
I20260812 06:17:07.587714 26793 log.cc:1079] T 531c6529b8d64d46a54b34e30e43af2e P cab28ff2fc704213a596d59a51cbe098: Deleting log segment in path: /tmp/dist-test-taskJUqZec/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415209139-26474-0/minicluster-data/ts-0-root/wals/531c6529b8d64d46a54b34e30e43af2e/wal-000000040 (ops 192-196)
I20260812 06:17:07.591615 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: LogGCOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.004s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:17:07.592157 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e): perf score=2.188937
I20260812 06:17:07.604000 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: FlushDeltaMemStoresOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.012s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4666,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:07.604506 26863 maintenance_manager.cc:419] P cab28ff2fc704213a596d59a51cbe098: Scheduling MajorDeltaCompactionOp(531c6529b8d64d46a54b34e30e43af2e): perf score=1.000000
I20260812 06:17:07.711648 26474 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.351s	user 1.934s	sys 0.181s
I20260812 06:17:07.815042 26474 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.103s	user 0.003s	sys 0.000s
I20260812 06:17:07.815599 26474 tablet_server.cc:179] TabletServer@127.25.218.129:0 shutting down...
I20260812 06:17:07.832005 26793 maintenance_manager.cc:643] P cab28ff2fc704213a596d59a51cbe098: MajorDeltaCompactionOp(531c6529b8d64d46a54b34e30e43af2e) complete. Timing: real 0.227s	user 0.147s	sys 0.079s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32938894,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":377,"lbm_read_time_us":16234,"lbm_reads_lt_1ms":771,"lbm_write_time_us":40247,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":16768,"thread_start_us":95,"threads_started":1,"update_count":3500}
I20260812 06:17:07.834174 26474 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:07.834542 26474 tablet_replica.cc:333] T 531c6529b8d64d46a54b34e30e43af2e P cab28ff2fc704213a596d59a51cbe098: stopping tablet replica
I20260812 06:17:07.834756 26474 raft_consensus.cc:2243] T 531c6529b8d64d46a54b34e30e43af2e P cab28ff2fc704213a596d59a51cbe098 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:07.834997 26474 raft_consensus.cc:2272] T 531c6529b8d64d46a54b34e30e43af2e P cab28ff2fc704213a596d59a51cbe098 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:07.851768 26474 tablet_server.cc:196] TabletServer@127.25.218.129:0 shutdown complete.
I20260812 06:17:07.895632 26474 master.cc:562] Master@127.25.218.190:45049 shutting down...
I20260812 06:17:07.899560 26474 raft_consensus.cc:2243] T 00000000000000000000000000000000 P f23944713bf2446282eef96305ec4672 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:07.899796 26474 raft_consensus.cc:2272] T 00000000000000000000000000000000 P f23944713bf2446282eef96305ec4672 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:07.899880 26474 tablet_replica.cc:333] T 00000000000000000000000000000000 P f23944713bf2446282eef96305ec4672: stopping tablet replica
I20260812 06:17:07.912708 26474 master.cc:584] Master@127.25.218.190:45049 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5894 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (12774 ms total)

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