[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:17:45.533691 29460 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.28.197.62:43723
I20260812 06:17:45.534600 29460 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:17:45.535161 29460 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:45.541117 29474 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:45.541203 29468 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:45.541316 29460 server_base.cc:1061] running on GCE node
W20260812 06:17:45.541460 29470 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:45.541894 29460 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:45.541987 29460 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:45.542042 29460 hybrid_clock.cc:648] HybridClock initialized: now 1786515465542040 us; error 0 us; skew 500 ppm
I20260812 06:17:45.543671 29460 webserver.cc:533] Webserver started at http://127.28.197.62:38469/ using document root <none> and password file <none>
I20260812 06:17:45.544159 29460 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:45.544217 29460 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:45.544430 29460 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:45.545943 29460 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465523567-29460-0/minicluster-data/master-0-root/instance:
uuid: "6b715049f77047c9b321f0787c917a60"
format_stamp: "Formatted at 2026-08-12 06:17:45 on dist-test-slave-q9h9"
I20260812 06:17:45.549100 29460 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:17:45.551178 29481 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:45.552114 29460 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:17:45.552222 29460 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465523567-29460-0/minicluster-data/master-0-root
uuid: "6b715049f77047c9b321f0787c917a60"
format_stamp: "Formatted at 2026-08-12 06:17:45 on dist-test-slave-q9h9"
I20260812 06:17:45.552312 29460 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465523567-29460-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465523567-29460-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465523567-29460-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:45.561159 29460 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:45.561647 29460 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:17:45.561780 29460 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:45.568516 29583 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.28.197.62:43723 every 8 connection(s)
I20260812 06:17:45.568516 29460 rpc_server.cc:307] RPC server started. Bound to: 127.28.197.62:43723
I20260812 06:17:45.570652 29585 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:45.575652 29585 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 6b715049f77047c9b321f0787c917a60: Bootstrap starting.
I20260812 06:17:45.577829 29585 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 6b715049f77047c9b321f0787c917a60: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:45.578678 29585 log.cc:826] T 00000000000000000000000000000000 P 6b715049f77047c9b321f0787c917a60: Log is configured to *not* fsync() on all Append() calls
I20260812 06:17:45.580147 29585 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 6b715049f77047c9b321f0787c917a60: No bootstrap required, opened a new log
I20260812 06:17:45.582721 29585 raft_consensus.cc:359] T 00000000000000000000000000000000 P 6b715049f77047c9b321f0787c917a60 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6b715049f77047c9b321f0787c917a60" member_type: VOTER }
I20260812 06:17:45.582868 29585 raft_consensus.cc:385] T 00000000000000000000000000000000 P 6b715049f77047c9b321f0787c917a60 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:45.582933 29585 raft_consensus.cc:740] T 00000000000000000000000000000000 P 6b715049f77047c9b321f0787c917a60 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 6b715049f77047c9b321f0787c917a60, State: Initialized, Role: FOLLOWER
I20260812 06:17:45.583487 29585 consensus_queue.cc:260] T 00000000000000000000000000000000 P 6b715049f77047c9b321f0787c917a60 [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: "6b715049f77047c9b321f0787c917a60" member_type: VOTER }
I20260812 06:17:45.583633 29585 raft_consensus.cc:399] T 00000000000000000000000000000000 P 6b715049f77047c9b321f0787c917a60 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:45.583698 29585 raft_consensus.cc:493] T 00000000000000000000000000000000 P 6b715049f77047c9b321f0787c917a60 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:45.583811 29585 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 6b715049f77047c9b321f0787c917a60 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:45.584515 29585 raft_consensus.cc:515] T 00000000000000000000000000000000 P 6b715049f77047c9b321f0787c917a60 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6b715049f77047c9b321f0787c917a60" member_type: VOTER }
I20260812 06:17:45.584905 29585 leader_election.cc:304] T 00000000000000000000000000000000 P 6b715049f77047c9b321f0787c917a60 [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: 6b715049f77047c9b321f0787c917a60; no voters: 
I20260812 06:17:45.585186 29585 leader_election.cc:290] T 00000000000000000000000000000000 P 6b715049f77047c9b321f0787c917a60 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:45.585286 29597 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 6b715049f77047c9b321f0787c917a60 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:45.585484 29597 raft_consensus.cc:697] T 00000000000000000000000000000000 P 6b715049f77047c9b321f0787c917a60 [term 1 LEADER]: Becoming Leader. State: Replica: 6b715049f77047c9b321f0787c917a60, State: Running, Role: LEADER
I20260812 06:17:45.585888 29597 consensus_queue.cc:237] T 00000000000000000000000000000000 P 6b715049f77047c9b321f0787c917a60 [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: "6b715049f77047c9b321f0787c917a60" member_type: VOTER }
I20260812 06:17:45.586051 29585 sys_catalog.cc:565] T 00000000000000000000000000000000 P 6b715049f77047c9b321f0787c917a60 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:45.587590 29601 sys_catalog.cc:455] T 00000000000000000000000000000000 P 6b715049f77047c9b321f0787c917a60 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 6b715049f77047c9b321f0787c917a60. Latest consensus state: current_term: 1 leader_uuid: "6b715049f77047c9b321f0787c917a60" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6b715049f77047c9b321f0787c917a60" member_type: VOTER } }
I20260812 06:17:45.587591 29599 sys_catalog.cc:455] T 00000000000000000000000000000000 P 6b715049f77047c9b321f0787c917a60 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "6b715049f77047c9b321f0787c917a60" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6b715049f77047c9b321f0787c917a60" member_type: VOTER } }
I20260812 06:17:45.587715 29601 sys_catalog.cc:458] T 00000000000000000000000000000000 P 6b715049f77047c9b321f0787c917a60 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:45.587750 29599 sys_catalog.cc:458] T 00000000000000000000000000000000 P 6b715049f77047c9b321f0787c917a60 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:45.588027 29618 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:45.588057 29460 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:45.590432 29618 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:45.594664 29618 catalog_manager.cc:1383] Generated new cluster ID: 1be9df0165f942abb6e9210a906ef401
I20260812 06:17:45.594717 29618 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:45.605209 29618 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:45.606246 29618 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:45.613883 29618 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 6b715049f77047c9b321f0787c917a60: Generated new TSK 0
I20260812 06:17:45.614543 29618 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:45.620609 29460 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:45.622957 29632 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:45.623035 29637 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:45.623042 29630 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:45.623313 29460 server_base.cc:1061] running on GCE node
I20260812 06:17:45.623466 29460 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:45.623507 29460 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:45.623526 29460 hybrid_clock.cc:648] HybridClock initialized: now 1786515465623526 us; error 0 us; skew 500 ppm
I20260812 06:17:45.624341 29460 webserver.cc:533] Webserver started at http://127.28.197.1:35593/ using document root <none> and password file <none>
I20260812 06:17:45.624500 29460 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:45.624552 29460 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:45.624624 29460 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:45.624946 29460 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465523567-29460-0/minicluster-data/ts-0-root/instance:
uuid: "5cd7e80a980c4a4ea0b627a490207008"
format_stamp: "Formatted at 2026-08-12 06:17:45 on dist-test-slave-q9h9"
I20260812 06:17:45.626623 29460 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:45.629480 29644 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:45.629848 29460 fs_manager.cc:730] Time spent opening block manager: real 0.003s	user 0.001s	sys 0.000s
I20260812 06:17:45.629925 29460 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465523567-29460-0/minicluster-data/ts-0-root
uuid: "5cd7e80a980c4a4ea0b627a490207008"
format_stamp: "Formatted at 2026-08-12 06:17:45 on dist-test-slave-q9h9"
I20260812 06:17:45.629987 29460 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465523567-29460-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465523567-29460-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465523567-29460-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:45.639889 29460 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:45.640223 29460 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:45.640575 29460 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:45.641327 29460 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:45.641378 29460 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:45.641420 29460 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:45.641451 29460 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:45.647655 29460 rpc_server.cc:307] RPC server started. Bound to: 127.28.197.1:41133
I20260812 06:17:45.647699 29770 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.28.197.1:41133 every 8 connection(s)
I20260812 06:17:45.656539 29771 heartbeater.cc:344] Connected to a master server at 127.28.197.62:43723
I20260812 06:17:45.656741 29771 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:45.657107 29771 heartbeater.cc:507] Master 127.28.197.62:43723 requested a full tablet report, sending...
I20260812 06:17:45.658504 29519 ts_manager.cc:194] Registered new tserver with Master: 5cd7e80a980c4a4ea0b627a490207008 (127.28.197.1:41133)
I20260812 06:17:45.659384 29460 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011178286s
I20260812 06:17:45.659982 29519 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:49932
I20260812 06:17:45.667773 29519 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:49942:
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:45.680852 29696 tablet_service.cc:1511] Processing CreateTablet for tablet 58c93dec2c1447ad9f545c7f4ab5f307 (DEFAULT_TABLE table=heavy-update-compaction-test [id=73812e5926ff4121b7481e6367a2d099]), partition=
I20260812 06:17:45.681278 29696 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 58c93dec2c1447ad9f545c7f4ab5f307. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:45.683331 29788 tablet_bootstrap.cc:492] T 58c93dec2c1447ad9f545c7f4ab5f307 P 5cd7e80a980c4a4ea0b627a490207008: Bootstrap starting.
I20260812 06:17:45.684243 29788 tablet_bootstrap.cc:654] T 58c93dec2c1447ad9f545c7f4ab5f307 P 5cd7e80a980c4a4ea0b627a490207008: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:45.685305 29788 tablet_bootstrap.cc:492] T 58c93dec2c1447ad9f545c7f4ab5f307 P 5cd7e80a980c4a4ea0b627a490207008: No bootstrap required, opened a new log
I20260812 06:17:45.685395 29788 ts_tablet_manager.cc:1403] T 58c93dec2c1447ad9f545c7f4ab5f307 P 5cd7e80a980c4a4ea0b627a490207008: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:45.685789 29788 raft_consensus.cc:359] T 58c93dec2c1447ad9f545c7f4ab5f307 P 5cd7e80a980c4a4ea0b627a490207008 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5cd7e80a980c4a4ea0b627a490207008" member_type: VOTER last_known_addr { host: "127.28.197.1" port: 41133 } }
I20260812 06:17:45.685900 29788 raft_consensus.cc:385] T 58c93dec2c1447ad9f545c7f4ab5f307 P 5cd7e80a980c4a4ea0b627a490207008 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:45.685935 29788 raft_consensus.cc:740] T 58c93dec2c1447ad9f545c7f4ab5f307 P 5cd7e80a980c4a4ea0b627a490207008 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 5cd7e80a980c4a4ea0b627a490207008, State: Initialized, Role: FOLLOWER
I20260812 06:17:45.686082 29788 consensus_queue.cc:260] T 58c93dec2c1447ad9f545c7f4ab5f307 P 5cd7e80a980c4a4ea0b627a490207008 [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: "5cd7e80a980c4a4ea0b627a490207008" member_type: VOTER last_known_addr { host: "127.28.197.1" port: 41133 } }
I20260812 06:17:45.686168 29788 raft_consensus.cc:399] T 58c93dec2c1447ad9f545c7f4ab5f307 P 5cd7e80a980c4a4ea0b627a490207008 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:45.686209 29788 raft_consensus.cc:493] T 58c93dec2c1447ad9f545c7f4ab5f307 P 5cd7e80a980c4a4ea0b627a490207008 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:45.686259 29788 raft_consensus.cc:3060] T 58c93dec2c1447ad9f545c7f4ab5f307 P 5cd7e80a980c4a4ea0b627a490207008 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:45.686935 29788 raft_consensus.cc:515] T 58c93dec2c1447ad9f545c7f4ab5f307 P 5cd7e80a980c4a4ea0b627a490207008 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5cd7e80a980c4a4ea0b627a490207008" member_type: VOTER last_known_addr { host: "127.28.197.1" port: 41133 } }
I20260812 06:17:45.687063 29788 leader_election.cc:304] T 58c93dec2c1447ad9f545c7f4ab5f307 P 5cd7e80a980c4a4ea0b627a490207008 [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: 5cd7e80a980c4a4ea0b627a490207008; no voters: 
I20260812 06:17:45.687260 29788 leader_election.cc:290] T 58c93dec2c1447ad9f545c7f4ab5f307 P 5cd7e80a980c4a4ea0b627a490207008 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:45.687361 29793 raft_consensus.cc:2804] T 58c93dec2c1447ad9f545c7f4ab5f307 P 5cd7e80a980c4a4ea0b627a490207008 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:45.687573 29793 raft_consensus.cc:697] T 58c93dec2c1447ad9f545c7f4ab5f307 P 5cd7e80a980c4a4ea0b627a490207008 [term 1 LEADER]: Becoming Leader. State: Replica: 5cd7e80a980c4a4ea0b627a490207008, State: Running, Role: LEADER
I20260812 06:17:45.687597 29788 ts_tablet_manager.cc:1434] T 58c93dec2c1447ad9f545c7f4ab5f307 P 5cd7e80a980c4a4ea0b627a490207008: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:17:45.687881 29771 heartbeater.cc:499] Master 127.28.197.62:43723 was elected leader, sending a full tablet report...
I20260812 06:17:45.688252 29793 consensus_queue.cc:237] T 58c93dec2c1447ad9f545c7f4ab5f307 P 5cd7e80a980c4a4ea0b627a490207008 [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: "5cd7e80a980c4a4ea0b627a490207008" member_type: VOTER last_known_addr { host: "127.28.197.1" port: 41133 } }
I20260812 06:17:45.690616 29519 catalog_manager.cc:5719] T 58c93dec2c1447ad9f545c7f4ab5f307 P 5cd7e80a980c4a4ea0b627a490207008 reported cstate change: term changed from 0 to 1, leader changed from <none> to 5cd7e80a980c4a4ea0b627a490207008 (127.28.197.1). New cstate: current_term: 1 leader_uuid: "5cd7e80a980c4a4ea0b627a490207008" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5cd7e80a980c4a4ea0b627a490207008" member_type: VOTER last_known_addr { host: "127.28.197.1" port: 41133 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:45.751672 29460 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.056s	user 0.009s	sys 0.016s
I20260812 06:17:45.898636 29772 maintenance_manager.cc:419] P 5cd7e80a980c4a4ea0b627a490207008: Scheduling FlushMRSOp(58c93dec2c1447ad9f545c7f4ab5f307): perf score=19.054940
I20260812 06:17:46.056686 29651 maintenance_manager.cc:643] P 5cd7e80a980c4a4ea0b627a490207008: FlushMRSOp(58c93dec2c1447ad9f545c7f4ab5f307) complete. Timing: real 0.158s	user 0.117s	sys 0.036s Metrics: {"bytes_written":12389530,"cfile_init":1,"compiler_manager_pool.queue_time_us":239,"delete_count":0,"dirs.queue_time_us":1593,"dirs.run_cpu_time_us":196,"dirs.run_wall_time_us":1332,"drs_written":1,"lbm_read_time_us":74,"lbm_reads_lt_1ms":4,"lbm_write_time_us":37487,"lbm_writes_lt_1ms":769,"mutex_wait_us":1275,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"spinlock_wait_cycles":210688,"thread_start_us":166,"threads_started":1,"update_count":1510}
I20260812 06:17:46.057619 29772 maintenance_manager.cc:419] P 5cd7e80a980c4a4ea0b627a490207008: Scheduling LogGCOp(58c93dec2c1447ad9f545c7f4ab5f307): free 20743880 bytes of WAL
I20260812 06:17:46.057895 29651 log_reader.cc:385] T 58c93dec2c1447ad9f545c7f4ab5f307: removed 2 log segments from log reader
I20260812 06:17:46.057950 29651 log.cc:1079] T 58c93dec2c1447ad9f545c7f4ab5f307 P 5cd7e80a980c4a4ea0b627a490207008: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/58c93dec2c1447ad9f545c7f4ab5f307/wal-000000001 (ops 1-6)
I20260812 06:17:46.058009 29651 log.cc:1079] T 58c93dec2c1447ad9f545c7f4ab5f307 P 5cd7e80a980c4a4ea0b627a490207008: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/58c93dec2c1447ad9f545c7f4ab5f307/wal-000000002 (ops 7-11)
I20260812 06:17:46.063321 29651 maintenance_manager.cc:643] P 5cd7e80a980c4a4ea0b627a490207008: LogGCOp(58c93dec2c1447ad9f545c7f4ab5f307) complete. Timing: real 0.006s	user 0.001s	sys 0.003s Metrics: {}
I20260812 06:17:46.063620 29772 maintenance_manager.cc:419] P 5cd7e80a980c4a4ea0b627a490207008: Scheduling UndoDeltaBlockGCOp(58c93dec2c1447ad9f545c7f4ab5f307): 16821647 bytes on disk
I20260812 06:17:46.064273 29651 maintenance_manager.cc:643] P 5cd7e80a980c4a4ea0b627a490207008: UndoDeltaBlockGCOp(58c93dec2c1447ad9f545c7f4ab5f307) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":71,"lbm_reads_lt_1ms":4}
I20260812 06:17:46.064828 29772 maintenance_manager.cc:419] P 5cd7e80a980c4a4ea0b627a490207008: Scheduling FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307): perf score=2.188937
I20260812 06:17:46.078372 29651 maintenance_manager.cc:643] P 5cd7e80a980c4a4ea0b627a490207008: FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307) complete. Timing: real 0.013s	user 0.004s	sys 0.007s Metrics: {"bytes_written":3610355,"delete_count":0,"lbm_write_time_us":4167,"lbm_writes_lt_1ms":91,"reinsert_count":0,"update_count":440}
I20260812 06:17:46.078778 29772 maintenance_manager.cc:419] P 5cd7e80a980c4a4ea0b627a490207008: Scheduling MajorDeltaCompactionOp(58c93dec2c1447ad9f545c7f4ab5f307): perf score=1.000000
I20260812 06:17:46.224905 29651 maintenance_manager.cc:643] P 5cd7e80a980c4a4ea0b627a490207008: MajorDeltaCompactionOp(58c93dec2c1447ad9f545c7f4ab5f307) complete. Timing: real 0.146s	user 0.107s	sys 0.035s Metrics: {"cfile_cache_miss":422,"cfile_cache_miss_bytes":20303008,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":569,"lbm_read_time_us":9755,"lbm_reads_lt_1ms":450,"lbm_write_time_us":23400,"lbm_writes_lt_1ms":433,"mutex_wait_us":37,"peak_mem_usage":49238594,"reinsert_count":0,"spinlock_wait_cycles":13696,"thread_start_us":340,"threads_started":5,"update_count":1950}
I20260812 06:17:46.225591 29772 maintenance_manager.cc:419] P 5cd7e80a980c4a4ea0b627a490207008: Scheduling FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307): perf score=10.126437
I20260812 06:17:46.264140 29651 maintenance_manager.cc:643] P 5cd7e80a980c4a4ea0b627a490207008: FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307) complete. Timing: real 0.038s	user 0.007s	sys 0.023s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":13893,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:46.264606 29772 maintenance_manager.cc:419] P 5cd7e80a980c4a4ea0b627a490207008: Scheduling FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307): perf score=2.188937
I20260812 06:17:46.278565 29651 maintenance_manager.cc:643] P 5cd7e80a980c4a4ea0b627a490207008: FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307) complete. Timing: real 0.014s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5369,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:46.278972 29772 maintenance_manager.cc:419] P 5cd7e80a980c4a4ea0b627a490207008: Scheduling MajorDeltaCompactionOp(58c93dec2c1447ad9f545c7f4ab5f307): perf score=1.000000
I20260812 06:17:46.415627 29651 maintenance_manager.cc:643] P 5cd7e80a980c4a4ea0b627a490207008: MajorDeltaCompactionOp(58c93dec2c1447ad9f545c7f4ab5f307) complete. Timing: real 0.137s	user 0.104s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713273,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":105,"lbm_read_time_us":9933,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24709,"lbm_writes_lt_1ms":443,"mutex_wait_us":25,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":60416,"update_count":2000}
I20260812 06:17:46.416584 29772 maintenance_manager.cc:419] P 5cd7e80a980c4a4ea0b627a490207008: Scheduling FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307): perf score=10.126437
I20260812 06:17:46.450139 29651 maintenance_manager.cc:643] P 5cd7e80a980c4a4ea0b627a490207008: FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307) complete. Timing: real 0.033s	user 0.025s	sys 0.003s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":12113,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:46.450593 29772 maintenance_manager.cc:419] P 5cd7e80a980c4a4ea0b627a490207008: Scheduling FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307): perf score=2.188937
I20260812 06:17:46.465562 29651 maintenance_manager.cc:643] P 5cd7e80a980c4a4ea0b627a490207008: FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307) complete. Timing: real 0.015s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5683,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:46.466157 29772 maintenance_manager.cc:419] P 5cd7e80a980c4a4ea0b627a490207008: Scheduling MajorDeltaCompactionOp(58c93dec2c1447ad9f545c7f4ab5f307): perf score=1.000000
I20260812 06:17:46.591939 29651 maintenance_manager.cc:643] P 5cd7e80a980c4a4ea0b627a490207008: MajorDeltaCompactionOp(58c93dec2c1447ad9f545c7f4ab5f307) complete. Timing: real 0.126s	user 0.094s	sys 0.031s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713271,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1226,"lbm_read_time_us":8988,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25561,"lbm_writes_lt_1ms":443,"mutex_wait_us":529,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":2000}
I20260812 06:17:46.592406 29772 maintenance_manager.cc:419] P 5cd7e80a980c4a4ea0b627a490207008: Scheduling FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307): perf score=10.126437
I20260812 06:17:46.640153 29651 maintenance_manager.cc:643] P 5cd7e80a980c4a4ea0b627a490207008: FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307) complete. Timing: real 0.048s	user 0.022s	sys 0.020s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":15361,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:46.640618 29772 maintenance_manager.cc:419] P 5cd7e80a980c4a4ea0b627a490207008: Scheduling FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307): perf score=2.188937
I20260812 06:17:46.651328 29651 maintenance_manager.cc:643] P 5cd7e80a980c4a4ea0b627a490207008: FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4301,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:46.651759 29772 maintenance_manager.cc:419] P 5cd7e80a980c4a4ea0b627a490207008: Scheduling MajorDeltaCompactionOp(58c93dec2c1447ad9f545c7f4ab5f307): perf score=1.000000
I20260812 06:17:46.800311 29651 maintenance_manager.cc:643] P 5cd7e80a980c4a4ea0b627a490207008: MajorDeltaCompactionOp(58c93dec2c1447ad9f545c7f4ab5f307) complete. Timing: real 0.148s	user 0.083s	sys 0.062s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713274,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":147,"lbm_read_time_us":9702,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26799,"lbm_writes_lt_1ms":443,"mutex_wait_us":37,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4352,"update_count":2000}
I20260812 06:17:46.801355 29772 maintenance_manager.cc:419] P 5cd7e80a980c4a4ea0b627a490207008: Scheduling FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307): perf score=10.126437
I20260812 06:17:46.846730 29651 maintenance_manager.cc:643] P 5cd7e80a980c4a4ea0b627a490207008: FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307) complete. Timing: real 0.045s	user 0.025s	sys 0.016s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":20592,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:46.847149 29772 maintenance_manager.cc:419] P 5cd7e80a980c4a4ea0b627a490207008: Scheduling FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307): perf score=2.188937
I20260812 06:17:46.857298 29651 maintenance_manager.cc:643] P 5cd7e80a980c4a4ea0b627a490207008: FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3777,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:46.858052 29772 maintenance_manager.cc:419] P 5cd7e80a980c4a4ea0b627a490207008: Scheduling MajorDeltaCompactionOp(58c93dec2c1447ad9f545c7f4ab5f307): perf score=1.000000
I20260812 06:17:46.981479 29651 maintenance_manager.cc:643] P 5cd7e80a980c4a4ea0b627a490207008: MajorDeltaCompactionOp(58c93dec2c1447ad9f545c7f4ab5f307) complete. Timing: real 0.123s	user 0.110s	sys 0.013s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713273,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":882,"lbm_read_time_us":8722,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23782,"lbm_writes_lt_1ms":443,"mutex_wait_us":295,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:17:46.981992 29772 maintenance_manager.cc:419] P 5cd7e80a980c4a4ea0b627a490207008: Scheduling FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307): perf score=10.126437
I20260812 06:17:47.016263 29651 maintenance_manager.cc:643] P 5cd7e80a980c4a4ea0b627a490207008: FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307) complete. Timing: real 0.034s	user 0.029s	sys 0.001s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":14082,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:47.016706 29772 maintenance_manager.cc:419] P 5cd7e80a980c4a4ea0b627a490207008: Scheduling FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307): perf score=2.188937
I20260812 06:17:47.031080 29651 maintenance_manager.cc:643] P 5cd7e80a980c4a4ea0b627a490207008: FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307) complete. Timing: real 0.014s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5454,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:47.031658 29772 maintenance_manager.cc:419] P 5cd7e80a980c4a4ea0b627a490207008: Scheduling MajorDeltaCompactionOp(58c93dec2c1447ad9f545c7f4ab5f307): perf score=1.000000
I20260812 06:17:47.156852 29651 maintenance_manager.cc:643] P 5cd7e80a980c4a4ea0b627a490207008: MajorDeltaCompactionOp(58c93dec2c1447ad9f545c7f4ab5f307) complete. Timing: real 0.125s	user 0.104s	sys 0.021s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713271,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":181,"lbm_read_time_us":8858,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23466,"lbm_writes_lt_1ms":443,"mutex_wait_us":18,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":15232,"update_count":2000}
I20260812 06:17:47.157364 29772 maintenance_manager.cc:419] P 5cd7e80a980c4a4ea0b627a490207008: Scheduling FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307): perf score=10.126437
I20260812 06:17:47.204600 29651 maintenance_manager.cc:643] P 5cd7e80a980c4a4ea0b627a490207008: FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307) complete. Timing: real 0.047s	user 0.010s	sys 0.031s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15842,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:47.205195 29772 maintenance_manager.cc:419] P 5cd7e80a980c4a4ea0b627a490207008: Scheduling FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307): perf score=2.188937
I20260812 06:17:47.215278 29651 maintenance_manager.cc:643] P 5cd7e80a980c4a4ea0b627a490207008: FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3800,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:47.215777 29772 maintenance_manager.cc:419] P 5cd7e80a980c4a4ea0b627a490207008: Scheduling MajorDeltaCompactionOp(58c93dec2c1447ad9f545c7f4ab5f307): perf score=1.000000
I20260812 06:17:47.356667 29651 maintenance_manager.cc:643] P 5cd7e80a980c4a4ea0b627a490207008: MajorDeltaCompactionOp(58c93dec2c1447ad9f545c7f4ab5f307) complete. Timing: real 0.141s	user 0.069s	sys 0.071s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713271,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":175,"lbm_read_time_us":10767,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23240,"lbm_writes_lt_1ms":443,"mutex_wait_us":67,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2000}
I20260812 06:17:47.357156 29772 maintenance_manager.cc:419] P 5cd7e80a980c4a4ea0b627a490207008: Scheduling FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307): perf score=10.126437
I20260812 06:17:47.398748 29651 maintenance_manager.cc:643] P 5cd7e80a980c4a4ea0b627a490207008: FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307) complete. Timing: real 0.041s	user 0.025s	sys 0.007s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":14131,"lbm_writes_lt_1ms":303,"mutex_wait_us":2,"reinsert_count":0,"update_count":1500}
I20260812 06:17:47.399219 29772 maintenance_manager.cc:419] P 5cd7e80a980c4a4ea0b627a490207008: Scheduling FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307): perf score=2.188937
I20260812 06:17:47.413980 29651 maintenance_manager.cc:643] P 5cd7e80a980c4a4ea0b627a490207008: FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5588,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:47.414430 29772 maintenance_manager.cc:419] P 5cd7e80a980c4a4ea0b627a490207008: Scheduling FlushMRSOp(58c93dec2c1447ad9f545c7f4ab5f307): perf score=1.000000
I20260812 06:17:47.444136 29651 maintenance_manager.cc:643] P 5cd7e80a980c4a4ea0b627a490207008: FlushMRSOp(58c93dec2c1447ad9f545c7f4ab5f307) complete. Timing: real 0.030s	user 0.024s	sys 0.002s Metrics: {"bytes_written":1275444,"cfile_init":1,"dirs.queue_time_us":51,"dirs.run_cpu_time_us":206,"dirs.run_wall_time_us":1762,"drs_written":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1592,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:47.444989 29772 maintenance_manager.cc:419] P 5cd7e80a980c4a4ea0b627a490207008: Scheduling LogGCOp(58c93dec2c1447ad9f545c7f4ab5f307): free 124710250 bytes of WAL
I20260812 06:17:47.445225 29651 log_reader.cc:385] T 58c93dec2c1447ad9f545c7f4ab5f307: removed 12 log segments from log reader
I20260812 06:17:47.445283 29651 log.cc:1079] T 58c93dec2c1447ad9f545c7f4ab5f307 P 5cd7e80a980c4a4ea0b627a490207008: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/58c93dec2c1447ad9f545c7f4ab5f307/wal-000000003 (ops 12-16)
I20260812 06:17:47.445329 29651 log.cc:1079] T 58c93dec2c1447ad9f545c7f4ab5f307 P 5cd7e80a980c4a4ea0b627a490207008: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/58c93dec2c1447ad9f545c7f4ab5f307/wal-000000004 (ops 17-21)
I20260812 06:17:47.445355 29651 log.cc:1079] T 58c93dec2c1447ad9f545c7f4ab5f307 P 5cd7e80a980c4a4ea0b627a490207008: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/58c93dec2c1447ad9f545c7f4ab5f307/wal-000000005 (ops 22-26)
I20260812 06:17:47.445389 29651 log.cc:1079] T 58c93dec2c1447ad9f545c7f4ab5f307 P 5cd7e80a980c4a4ea0b627a490207008: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/58c93dec2c1447ad9f545c7f4ab5f307/wal-000000006 (ops 27-31)
I20260812 06:17:47.445415 29651 log.cc:1079] T 58c93dec2c1447ad9f545c7f4ab5f307 P 5cd7e80a980c4a4ea0b627a490207008: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/58c93dec2c1447ad9f545c7f4ab5f307/wal-000000007 (ops 32-36)
I20260812 06:17:47.445441 29651 log.cc:1079] T 58c93dec2c1447ad9f545c7f4ab5f307 P 5cd7e80a980c4a4ea0b627a490207008: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/58c93dec2c1447ad9f545c7f4ab5f307/wal-000000008 (ops 37-41)
I20260812 06:17:47.445467 29651 log.cc:1079] T 58c93dec2c1447ad9f545c7f4ab5f307 P 5cd7e80a980c4a4ea0b627a490207008: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/58c93dec2c1447ad9f545c7f4ab5f307/wal-000000009 (ops 42-46)
I20260812 06:17:47.445492 29651 log.cc:1079] T 58c93dec2c1447ad9f545c7f4ab5f307 P 5cd7e80a980c4a4ea0b627a490207008: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/58c93dec2c1447ad9f545c7f4ab5f307/wal-000000010 (ops 47-51)
I20260812 06:17:47.445523 29651 log.cc:1079] T 58c93dec2c1447ad9f545c7f4ab5f307 P 5cd7e80a980c4a4ea0b627a490207008: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/58c93dec2c1447ad9f545c7f4ab5f307/wal-000000011 (ops 52-56)
I20260812 06:17:47.445554 29651 log.cc:1079] T 58c93dec2c1447ad9f545c7f4ab5f307 P 5cd7e80a980c4a4ea0b627a490207008: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/58c93dec2c1447ad9f545c7f4ab5f307/wal-000000012 (ops 57-61)
I20260812 06:17:47.445580 29651 log.cc:1079] T 58c93dec2c1447ad9f545c7f4ab5f307 P 5cd7e80a980c4a4ea0b627a490207008: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/58c93dec2c1447ad9f545c7f4ab5f307/wal-000000013 (ops 62-66)
I20260812 06:17:47.445606 29651 log.cc:1079] T 58c93dec2c1447ad9f545c7f4ab5f307 P 5cd7e80a980c4a4ea0b627a490207008: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/58c93dec2c1447ad9f545c7f4ab5f307/wal-000000014 (ops 67-71)
I20260812 06:17:47.473235 29651 maintenance_manager.cc:643] P 5cd7e80a980c4a4ea0b627a490207008: LogGCOp(58c93dec2c1447ad9f545c7f4ab5f307) complete. Timing: real 0.028s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:17:47.473595 29772 maintenance_manager.cc:419] P 5cd7e80a980c4a4ea0b627a490207008: Scheduling FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307): perf score=3.181125
I20260812 06:17:47.484833 29651 maintenance_manager.cc:643] P 5cd7e80a980c4a4ea0b627a490207008: FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4132,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:47.485256 29772 maintenance_manager.cc:419] P 5cd7e80a980c4a4ea0b627a490207008: Scheduling FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307): perf score=2.188937
I20260812 06:17:47.507113 29651 maintenance_manager.cc:643] P 5cd7e80a980c4a4ea0b627a490207008: FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307) complete. Timing: real 0.022s	user 0.006s	sys 0.015s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5283,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:47.507599 29772 maintenance_manager.cc:419] P 5cd7e80a980c4a4ea0b627a490207008: Scheduling UndoDeltaBlockGCOp(58c93dec2c1447ad9f545c7f4ab5f307): 483 bytes on disk
I20260812 06:17:47.508004 29651 maintenance_manager.cc:643] P 5cd7e80a980c4a4ea0b627a490207008: UndoDeltaBlockGCOp(58c93dec2c1447ad9f545c7f4ab5f307) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4}
I20260812 06:17:47.508481 29772 maintenance_manager.cc:419] P 5cd7e80a980c4a4ea0b627a490207008: Scheduling MajorDeltaCompactionOp(58c93dec2c1447ad9f545c7f4ab5f307): perf score=1.000000
I20260812 06:17:47.704356 29651 maintenance_manager.cc:643] P 5cd7e80a980c4a4ea0b627a490207008: MajorDeltaCompactionOp(58c93dec2c1447ad9f545c7f4ab5f307) complete. Timing: real 0.196s	user 0.113s	sys 0.079s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918326,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1448,"lbm_read_time_us":14278,"lbm_reads_lt_1ms":674,"lbm_write_time_us":34235,"lbm_writes_lt_1ms":643,"mutex_wait_us":585,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1280,"thread_start_us":89,"threads_started":1,"update_count":3000}
I20260812 06:17:47.704816 29772 maintenance_manager.cc:419] P 5cd7e80a980c4a4ea0b627a490207008: Scheduling FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307): perf score=14.095187
I20260812 06:17:47.760082 29651 maintenance_manager.cc:643] P 5cd7e80a980c4a4ea0b627a490207008: FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307) complete. Timing: real 0.055s	user 0.036s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18800,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:47.760535 29772 maintenance_manager.cc:419] P 5cd7e80a980c4a4ea0b627a490207008: Scheduling FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307): perf score=2.188937
I20260812 06:17:47.770144 29651 maintenance_manager.cc:643] P 5cd7e80a980c4a4ea0b627a490207008: FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307) complete. Timing: real 0.009s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3693,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:47.770496 29772 maintenance_manager.cc:419] P 5cd7e80a980c4a4ea0b627a490207008: Scheduling MajorDeltaCompactionOp(58c93dec2c1447ad9f545c7f4ab5f307): perf score=1.000000
I20260812 06:17:47.939280 29651 maintenance_manager.cc:643] P 5cd7e80a980c4a4ea0b627a490207008: MajorDeltaCompactionOp(58c93dec2c1447ad9f545c7f4ab5f307) complete. Timing: real 0.169s	user 0.099s	sys 0.067s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":552,"lbm_read_time_us":11784,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30082,"lbm_writes_lt_1ms":543,"mutex_wait_us":28,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2500}
I20260812 06:17:47.939779 29772 maintenance_manager.cc:419] P 5cd7e80a980c4a4ea0b627a490207008: Scheduling FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307): perf score=11.118625
I20260812 06:17:47.974344 29651 maintenance_manager.cc:643] P 5cd7e80a980c4a4ea0b627a490207008: FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307) complete. Timing: real 0.034s	user 0.014s	sys 0.020s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":15002,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:47.974814 29772 maintenance_manager.cc:419] P 5cd7e80a980c4a4ea0b627a490207008: Scheduling FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307): perf score=2.188937
I20260812 06:17:47.990795 29651 maintenance_manager.cc:643] P 5cd7e80a980c4a4ea0b627a490207008: FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307) complete. Timing: real 0.016s	user 0.003s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4355,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:47.991312 29772 maintenance_manager.cc:419] P 5cd7e80a980c4a4ea0b627a490207008: Scheduling MajorDeltaCompactionOp(58c93dec2c1447ad9f545c7f4ab5f307): perf score=1.000000
I20260812 06:17:48.127403 29651 maintenance_manager.cc:643] P 5cd7e80a980c4a4ea0b627a490207008: MajorDeltaCompactionOp(58c93dec2c1447ad9f545c7f4ab5f307) complete. Timing: real 0.136s	user 0.111s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713264,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":129,"lbm_read_time_us":7335,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24050,"lbm_writes_lt_1ms":443,"mutex_wait_us":52,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:48.128023 29772 maintenance_manager.cc:419] P 5cd7e80a980c4a4ea0b627a490207008: Scheduling FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307): perf score=11.118625
I20260812 06:17:48.163381 29651 maintenance_manager.cc:643] P 5cd7e80a980c4a4ea0b627a490207008: FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307) complete. Timing: real 0.035s	user 0.018s	sys 0.015s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15127,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:48.164465 29772 maintenance_manager.cc:419] P 5cd7e80a980c4a4ea0b627a490207008: Scheduling FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307): perf score=2.188937
I20260812 06:17:48.186698 29651 maintenance_manager.cc:643] P 5cd7e80a980c4a4ea0b627a490207008: FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307) complete. Timing: real 0.022s	user 0.001s	sys 0.011s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4868,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:48.187147 29772 maintenance_manager.cc:419] P 5cd7e80a980c4a4ea0b627a490207008: Scheduling FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307): perf score=2.188937
I20260812 06:17:48.196738 29651 maintenance_manager.cc:643] P 5cd7e80a980c4a4ea0b627a490207008: FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307) complete. Timing: real 0.009s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3744,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:48.197137 29772 maintenance_manager.cc:419] P 5cd7e80a980c4a4ea0b627a490207008: Scheduling MajorDeltaCompactionOp(58c93dec2c1447ad9f545c7f4ab5f307): perf score=1.000000
I20260812 06:17:48.338593 29651 maintenance_manager.cc:643] P 5cd7e80a980c4a4ea0b627a490207008: MajorDeltaCompactionOp(58c93dec2c1447ad9f545c7f4ab5f307) complete. Timing: real 0.141s	user 0.119s	sys 0.020s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815794,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":785,"lbm_read_time_us":9781,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29174,"lbm_writes_lt_1ms":543,"mutex_wait_us":329,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:48.339125 29772 maintenance_manager.cc:419] P 5cd7e80a980c4a4ea0b627a490207008: Scheduling FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307): perf score=11.118625
I20260812 06:17:48.376539 29651 maintenance_manager.cc:643] P 5cd7e80a980c4a4ea0b627a490207008: FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307) complete. Timing: real 0.037s	user 0.016s	sys 0.016s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":14374,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:48.376996 29772 maintenance_manager.cc:419] P 5cd7e80a980c4a4ea0b627a490207008: Scheduling FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307): perf score=2.188937
I20260812 06:17:48.390681 29651 maintenance_manager.cc:643] P 5cd7e80a980c4a4ea0b627a490207008: FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307) complete. Timing: real 0.014s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3971,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:48.391121 29772 maintenance_manager.cc:419] P 5cd7e80a980c4a4ea0b627a490207008: Scheduling FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307): perf score=2.188937
I20260812 06:17:48.403529 29651 maintenance_manager.cc:643] P 5cd7e80a980c4a4ea0b627a490207008: FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4824,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:48.403896 29772 maintenance_manager.cc:419] P 5cd7e80a980c4a4ea0b627a490207008: Scheduling MajorDeltaCompactionOp(58c93dec2c1447ad9f545c7f4ab5f307): perf score=1.000000
I20260812 06:17:48.562397 29651 maintenance_manager.cc:643] P 5cd7e80a980c4a4ea0b627a490207008: MajorDeltaCompactionOp(58c93dec2c1447ad9f545c7f4ab5f307) complete. Timing: real 0.158s	user 0.123s	sys 0.021s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815795,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":650,"lbm_read_time_us":10576,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29412,"lbm_writes_lt_1ms":543,"mutex_wait_us":326,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:48.562919 29772 maintenance_manager.cc:419] P 5cd7e80a980c4a4ea0b627a490207008: Scheduling FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307): perf score=14.095187
I20260812 06:17:48.617257 29651 maintenance_manager.cc:643] P 5cd7e80a980c4a4ea0b627a490207008: FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307) complete. Timing: real 0.054s	user 0.032s	sys 0.018s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24082,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:48.617810 29772 maintenance_manager.cc:419] P 5cd7e80a980c4a4ea0b627a490207008: Scheduling FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307): perf score=2.188937
I20260812 06:17:48.629241 29651 maintenance_manager.cc:643] P 5cd7e80a980c4a4ea0b627a490207008: FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307) complete. Timing: real 0.011s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3868,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:48.629678 29772 maintenance_manager.cc:419] P 5cd7e80a980c4a4ea0b627a490207008: Scheduling MajorDeltaCompactionOp(58c93dec2c1447ad9f545c7f4ab5f307): perf score=1.000000
I20260812 06:17:48.805878 29651 maintenance_manager.cc:643] P 5cd7e80a980c4a4ea0b627a490207008: MajorDeltaCompactionOp(58c93dec2c1447ad9f545c7f4ab5f307) complete. Timing: real 0.176s	user 0.120s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":926,"lbm_read_time_us":11082,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29604,"lbm_writes_lt_1ms":543,"mutex_wait_us":347,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:48.806463 29772 maintenance_manager.cc:419] P 5cd7e80a980c4a4ea0b627a490207008: Scheduling FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307): perf score=14.095187
I20260812 06:17:48.873507 29651 maintenance_manager.cc:643] P 5cd7e80a980c4a4ea0b627a490207008: FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307) complete. Timing: real 0.067s	user 0.041s	sys 0.009s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24515,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:48.874055 29772 maintenance_manager.cc:419] P 5cd7e80a980c4a4ea0b627a490207008: Scheduling FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307): perf score=2.188937
I20260812 06:17:48.889394 29651 maintenance_manager.cc:643] P 5cd7e80a980c4a4ea0b627a490207008: FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5650,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:48.889947 29772 maintenance_manager.cc:419] P 5cd7e80a980c4a4ea0b627a490207008: Scheduling FlushMRSOp(58c93dec2c1447ad9f545c7f4ab5f307): perf score=1.000000
I20260812 06:17:48.917172 29651 maintenance_manager.cc:643] P 5cd7e80a980c4a4ea0b627a490207008: FlushMRSOp(58c93dec2c1447ad9f545c7f4ab5f307) complete. Timing: real 0.027s	user 0.021s	sys 0.005s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":35,"dirs.run_cpu_time_us":185,"dirs.run_wall_time_us":1070,"drs_written":1,"lbm_read_time_us":36,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1456,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:48.917970 29772 maintenance_manager.cc:419] P 5cd7e80a980c4a4ea0b627a490207008: Scheduling LogGCOp(58c93dec2c1447ad9f545c7f4ab5f307): free 133477506 bytes of WAL
I20260812 06:17:48.918231 29651 log_reader.cc:385] T 58c93dec2c1447ad9f545c7f4ab5f307: removed 13 log segments from log reader
I20260812 06:17:48.918282 29651 log.cc:1079] T 58c93dec2c1447ad9f545c7f4ab5f307 P 5cd7e80a980c4a4ea0b627a490207008: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/58c93dec2c1447ad9f545c7f4ab5f307/wal-000000015 (ops 72-76)
I20260812 06:17:48.918321 29651 log.cc:1079] T 58c93dec2c1447ad9f545c7f4ab5f307 P 5cd7e80a980c4a4ea0b627a490207008: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/58c93dec2c1447ad9f545c7f4ab5f307/wal-000000016 (ops 77-81)
I20260812 06:17:48.918354 29651 log.cc:1079] T 58c93dec2c1447ad9f545c7f4ab5f307 P 5cd7e80a980c4a4ea0b627a490207008: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/58c93dec2c1447ad9f545c7f4ab5f307/wal-000000017 (ops 82-86)
I20260812 06:17:48.918387 29651 log.cc:1079] T 58c93dec2c1447ad9f545c7f4ab5f307 P 5cd7e80a980c4a4ea0b627a490207008: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/58c93dec2c1447ad9f545c7f4ab5f307/wal-000000018 (ops 87-91)
I20260812 06:17:48.918421 29651 log.cc:1079] T 58c93dec2c1447ad9f545c7f4ab5f307 P 5cd7e80a980c4a4ea0b627a490207008: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/58c93dec2c1447ad9f545c7f4ab5f307/wal-000000019 (ops 92-96)
I20260812 06:17:48.918452 29651 log.cc:1079] T 58c93dec2c1447ad9f545c7f4ab5f307 P 5cd7e80a980c4a4ea0b627a490207008: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/58c93dec2c1447ad9f545c7f4ab5f307/wal-000000020 (ops 97-101)
I20260812 06:17:48.918481 29651 log.cc:1079] T 58c93dec2c1447ad9f545c7f4ab5f307 P 5cd7e80a980c4a4ea0b627a490207008: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/58c93dec2c1447ad9f545c7f4ab5f307/wal-000000021 (ops 102-106)
I20260812 06:17:48.918512 29651 log.cc:1079] T 58c93dec2c1447ad9f545c7f4ab5f307 P 5cd7e80a980c4a4ea0b627a490207008: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/58c93dec2c1447ad9f545c7f4ab5f307/wal-000000022 (ops 107-111)
I20260812 06:17:48.918543 29651 log.cc:1079] T 58c93dec2c1447ad9f545c7f4ab5f307 P 5cd7e80a980c4a4ea0b627a490207008: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/58c93dec2c1447ad9f545c7f4ab5f307/wal-000000023 (ops 112-116)
I20260812 06:17:48.918574 29651 log.cc:1079] T 58c93dec2c1447ad9f545c7f4ab5f307 P 5cd7e80a980c4a4ea0b627a490207008: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/58c93dec2c1447ad9f545c7f4ab5f307/wal-000000024 (ops 117-121)
I20260812 06:17:48.918605 29651 log.cc:1079] T 58c93dec2c1447ad9f545c7f4ab5f307 P 5cd7e80a980c4a4ea0b627a490207008: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/58c93dec2c1447ad9f545c7f4ab5f307/wal-000000025 (ops 122-126)
I20260812 06:17:48.918637 29651 log.cc:1079] T 58c93dec2c1447ad9f545c7f4ab5f307 P 5cd7e80a980c4a4ea0b627a490207008: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/58c93dec2c1447ad9f545c7f4ab5f307/wal-000000026 (ops 127-131)
I20260812 06:17:48.918679 29651 log.cc:1079] T 58c93dec2c1447ad9f545c7f4ab5f307 P 5cd7e80a980c4a4ea0b627a490207008: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/58c93dec2c1447ad9f545c7f4ab5f307/wal-000000027 (ops 132-136)
I20260812 06:17:48.945525 29651 maintenance_manager.cc:643] P 5cd7e80a980c4a4ea0b627a490207008: LogGCOp(58c93dec2c1447ad9f545c7f4ab5f307) complete. Timing: real 0.027s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:17:48.945983 29772 maintenance_manager.cc:419] P 5cd7e80a980c4a4ea0b627a490207008: Scheduling UndoDeltaBlockGCOp(58c93dec2c1447ad9f545c7f4ab5f307): 482 bytes on disk
I20260812 06:17:48.946542 29651 maintenance_manager.cc:643] P 5cd7e80a980c4a4ea0b627a490207008: UndoDeltaBlockGCOp(58c93dec2c1447ad9f545c7f4ab5f307) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":69,"lbm_reads_lt_1ms":4}
I20260812 06:17:48.947153 29772 maintenance_manager.cc:419] P 5cd7e80a980c4a4ea0b627a490207008: Scheduling FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307): perf score=3.181125
I20260812 06:17:48.963955 29651 maintenance_manager.cc:643] P 5cd7e80a980c4a4ea0b627a490207008: FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307) complete. Timing: real 0.017s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4882125,"delete_count":0,"lbm_write_time_us":6789,"lbm_writes_lt_1ms":122,"reinsert_count":0,"update_count":595}
I20260812 06:17:48.964301 29772 maintenance_manager.cc:419] P 5cd7e80a980c4a4ea0b627a490207008: Scheduling FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307): perf score=2.188937
I20260812 06:17:48.972273 29651 maintenance_manager.cc:643] P 5cd7e80a980c4a4ea0b627a490207008: FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307) complete. Timing: real 0.008s	user 0.003s	sys 0.003s Metrics: {"bytes_written":3323180,"delete_count":0,"lbm_write_time_us":2911,"lbm_writes_lt_1ms":84,"reinsert_count":0,"update_count":405}
I20260812 06:17:48.972628 29772 maintenance_manager.cc:419] P 5cd7e80a980c4a4ea0b627a490207008: Scheduling MajorDeltaCompactionOp(58c93dec2c1447ad9f545c7f4ab5f307): perf score=1.000000
I20260812 06:17:49.183247 29651 maintenance_manager.cc:643] P 5cd7e80a980c4a4ea0b627a490207008: MajorDeltaCompactionOp(58c93dec2c1447ad9f545c7f4ab5f307) complete. Timing: real 0.210s	user 0.170s	sys 0.037s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020732,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":5191,"lbm_read_time_us":16005,"lbm_reads_lt_1ms":774,"lbm_write_time_us":36198,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"thread_start_us":1709,"threads_started":1,"update_count":3500}
I20260812 06:17:49.186302 29772 maintenance_manager.cc:419] P 5cd7e80a980c4a4ea0b627a490207008: Scheduling FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307): perf score=15.087375
I20260812 06:17:49.251191 29651 maintenance_manager.cc:643] P 5cd7e80a980c4a4ea0b627a490207008: FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307) complete. Timing: real 0.065s	user 0.022s	sys 0.029s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":25827,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":412,"reinsert_count":0,"update_count":2050}
I20260812 06:17:49.251675 29772 maintenance_manager.cc:419] P 5cd7e80a980c4a4ea0b627a490207008: Scheduling FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307): perf score=6.157687
I20260812 06:17:49.270481 29651 maintenance_manager.cc:643] P 5cd7e80a980c4a4ea0b627a490207008: FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307) complete. Timing: real 0.019s	user 0.014s	sys 0.004s Metrics: {"bytes_written":7794837,"delete_count":0,"lbm_write_time_us":7970,"lbm_writes_lt_1ms":193,"reinsert_count":0,"update_count":950}
I20260812 06:17:49.270915 29772 maintenance_manager.cc:419] P 5cd7e80a980c4a4ea0b627a490207008: Scheduling MajorDeltaCompactionOp(58c93dec2c1447ad9f545c7f4ab5f307): perf score=1.000000
I20260812 06:17:49.429610 29651 maintenance_manager.cc:643] P 5cd7e80a980c4a4ea0b627a490207008: MajorDeltaCompactionOp(58c93dec2c1447ad9f545c7f4ab5f307) complete. Timing: real 0.159s	user 0.138s	sys 0.020s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918096,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":325,"lbm_read_time_us":11617,"lbm_reads_lt_1ms":672,"lbm_write_time_us":32432,"lbm_writes_lt_1ms":643,"mutex_wait_us":73,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":9344,"update_count":3000}
I20260812 06:17:49.430351 29772 maintenance_manager.cc:419] P 5cd7e80a980c4a4ea0b627a490207008: Scheduling FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307): perf score=14.095187
I20260812 06:17:49.482345 29651 maintenance_manager.cc:643] P 5cd7e80a980c4a4ea0b627a490207008: FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307) complete. Timing: real 0.052s	user 0.027s	sys 0.022s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21688,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:49.482896 29772 maintenance_manager.cc:419] P 5cd7e80a980c4a4ea0b627a490207008: Scheduling FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307): perf score=2.188937
I20260812 06:17:49.493669 29651 maintenance_manager.cc:643] P 5cd7e80a980c4a4ea0b627a490207008: FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307) complete. Timing: real 0.011s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4006,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:49.494156 29772 maintenance_manager.cc:419] P 5cd7e80a980c4a4ea0b627a490207008: Scheduling MajorDeltaCompactionOp(58c93dec2c1447ad9f545c7f4ab5f307): perf score=1.000000
I20260812 06:17:49.649952 29651 maintenance_manager.cc:643] P 5cd7e80a980c4a4ea0b627a490207008: MajorDeltaCompactionOp(58c93dec2c1447ad9f545c7f4ab5f307) complete. Timing: real 0.156s	user 0.113s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1206,"lbm_read_time_us":10636,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29046,"lbm_writes_lt_1ms":543,"mutex_wait_us":301,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2500}
I20260812 06:17:49.650539 29772 maintenance_manager.cc:419] P 5cd7e80a980c4a4ea0b627a490207008: Scheduling FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307): perf score=14.095187
I20260812 06:17:49.709985 29651 maintenance_manager.cc:643] P 5cd7e80a980c4a4ea0b627a490207008: FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307) complete. Timing: real 0.059s	user 0.027s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":26701,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":400,"reinsert_count":0,"update_count":2000}
I20260812 06:17:49.710495 29772 maintenance_manager.cc:419] P 5cd7e80a980c4a4ea0b627a490207008: Scheduling FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307): perf score=2.188937
I20260812 06:17:49.720059 29651 maintenance_manager.cc:643] P 5cd7e80a980c4a4ea0b627a490207008: FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3661,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:49.720530 29772 maintenance_manager.cc:419] P 5cd7e80a980c4a4ea0b627a490207008: Scheduling MajorDeltaCompactionOp(58c93dec2c1447ad9f545c7f4ab5f307): perf score=1.000000
I20260812 06:17:49.879658 29651 maintenance_manager.cc:643] P 5cd7e80a980c4a4ea0b627a490207008: MajorDeltaCompactionOp(58c93dec2c1447ad9f545c7f4ab5f307) complete. Timing: real 0.159s	user 0.095s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":224,"lbm_read_time_us":11417,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27076,"lbm_writes_lt_1ms":543,"mutex_wait_us":24,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7808,"update_count":2500}
I20260812 06:17:49.880136 29772 maintenance_manager.cc:419] P 5cd7e80a980c4a4ea0b627a490207008: Scheduling FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307): perf score=14.095187
I20260812 06:17:49.931226 29651 maintenance_manager.cc:643] P 5cd7e80a980c4a4ea0b627a490207008: FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307) complete. Timing: real 0.051s	user 0.023s	sys 0.023s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20795,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:49.931794 29772 maintenance_manager.cc:419] P 5cd7e80a980c4a4ea0b627a490207008: Scheduling FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307): perf score=2.188937
I20260812 06:17:49.947304 29651 maintenance_manager.cc:643] P 5cd7e80a980c4a4ea0b627a490207008: FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307) complete. Timing: real 0.015s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6119,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:49.949083 29772 maintenance_manager.cc:419] P 5cd7e80a980c4a4ea0b627a490207008: Scheduling MajorDeltaCompactionOp(58c93dec2c1447ad9f545c7f4ab5f307): perf score=1.000000
I20260812 06:17:50.098084 29651 maintenance_manager.cc:643] P 5cd7e80a980c4a4ea0b627a490207008: MajorDeltaCompactionOp(58c93dec2c1447ad9f545c7f4ab5f307) complete. Timing: real 0.149s	user 0.099s	sys 0.049s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":163,"lbm_read_time_us":10513,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26191,"lbm_writes_lt_1ms":543,"mutex_wait_us":67,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:17:50.098632 29772 maintenance_manager.cc:419] P 5cd7e80a980c4a4ea0b627a490207008: Scheduling FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307): perf score=14.095187
I20260812 06:17:50.155027 29651 maintenance_manager.cc:643] P 5cd7e80a980c4a4ea0b627a490207008: FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307) complete. Timing: real 0.056s	user 0.027s	sys 0.029s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20707,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:50.155594 29772 maintenance_manager.cc:419] P 5cd7e80a980c4a4ea0b627a490207008: Scheduling FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307): perf score=2.188937
I20260812 06:17:50.169979 29651 maintenance_manager.cc:643] P 5cd7e80a980c4a4ea0b627a490207008: FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307) complete. Timing: real 0.014s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5558,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:50.170447 29772 maintenance_manager.cc:419] P 5cd7e80a980c4a4ea0b627a490207008: Scheduling FlushMRSOp(58c93dec2c1447ad9f545c7f4ab5f307): perf score=1.000000
I20260812 06:17:50.198668 29651 maintenance_manager.cc:643] P 5cd7e80a980c4a4ea0b627a490207008: FlushMRSOp(58c93dec2c1447ad9f545c7f4ab5f307) complete. Timing: real 0.028s	user 0.022s	sys 0.005s Metrics: {"bytes_written":1152512,"cfile_init":1,"dirs.queue_time_us":57,"dirs.run_cpu_time_us":169,"dirs.run_wall_time_us":1051,"drs_written":1,"lbm_read_time_us":36,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1434,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:50.199383 29772 maintenance_manager.cc:419] P 5cd7e80a980c4a4ea0b627a490207008: Scheduling MajorDeltaCompactionOp(58c93dec2c1447ad9f545c7f4ab5f307): perf score=1.000000
I20260812 06:17:50.364058 29651 maintenance_manager.cc:643] P 5cd7e80a980c4a4ea0b627a490207008: MajorDeltaCompactionOp(58c93dec2c1447ad9f545c7f4ab5f307) complete. Timing: real 0.165s	user 0.115s	sys 0.050s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":110,"lbm_read_time_us":12592,"lbm_reads_lt_1ms":564,"lbm_write_time_us":27820,"lbm_writes_lt_1ms":543,"mutex_wait_us":19,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":18560,"update_count":2500}
I20260812 06:17:50.365006 29772 maintenance_manager.cc:419] P 5cd7e80a980c4a4ea0b627a490207008: Scheduling LogGCOp(58c93dec2c1447ad9f545c7f4ab5f307): free 111786447 bytes of WAL
I20260812 06:17:50.365309 29651 log_reader.cc:385] T 58c93dec2c1447ad9f545c7f4ab5f307: removed 11 log segments from log reader
I20260812 06:17:50.365382 29651 log.cc:1079] T 58c93dec2c1447ad9f545c7f4ab5f307 P 5cd7e80a980c4a4ea0b627a490207008: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/58c93dec2c1447ad9f545c7f4ab5f307/wal-000000028 (ops 137-140)
I20260812 06:17:50.365433 29651 log.cc:1079] T 58c93dec2c1447ad9f545c7f4ab5f307 P 5cd7e80a980c4a4ea0b627a490207008: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/58c93dec2c1447ad9f545c7f4ab5f307/wal-000000029 (ops 141-145)
I20260812 06:17:50.365473 29651 log.cc:1079] T 58c93dec2c1447ad9f545c7f4ab5f307 P 5cd7e80a980c4a4ea0b627a490207008: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/58c93dec2c1447ad9f545c7f4ab5f307/wal-000000030 (ops 146-150)
I20260812 06:17:50.365509 29651 log.cc:1079] T 58c93dec2c1447ad9f545c7f4ab5f307 P 5cd7e80a980c4a4ea0b627a490207008: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/58c93dec2c1447ad9f545c7f4ab5f307/wal-000000031 (ops 151-154)
I20260812 06:17:50.365545 29651 log.cc:1079] T 58c93dec2c1447ad9f545c7f4ab5f307 P 5cd7e80a980c4a4ea0b627a490207008: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/58c93dec2c1447ad9f545c7f4ab5f307/wal-000000032 (ops 155-159)
I20260812 06:17:50.365581 29651 log.cc:1079] T 58c93dec2c1447ad9f545c7f4ab5f307 P 5cd7e80a980c4a4ea0b627a490207008: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/58c93dec2c1447ad9f545c7f4ab5f307/wal-000000033 (ops 160-164)
I20260812 06:17:50.365618 29651 log.cc:1079] T 58c93dec2c1447ad9f545c7f4ab5f307 P 5cd7e80a980c4a4ea0b627a490207008: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/58c93dec2c1447ad9f545c7f4ab5f307/wal-000000034 (ops 165-169)
I20260812 06:17:50.365654 29651 log.cc:1079] T 58c93dec2c1447ad9f545c7f4ab5f307 P 5cd7e80a980c4a4ea0b627a490207008: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/58c93dec2c1447ad9f545c7f4ab5f307/wal-000000035 (ops 170-174)
I20260812 06:17:50.365688 29651 log.cc:1079] T 58c93dec2c1447ad9f545c7f4ab5f307 P 5cd7e80a980c4a4ea0b627a490207008: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/58c93dec2c1447ad9f545c7f4ab5f307/wal-000000036 (ops 175-179)
I20260812 06:17:50.365728 29651 log.cc:1079] T 58c93dec2c1447ad9f545c7f4ab5f307 P 5cd7e80a980c4a4ea0b627a490207008: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/58c93dec2c1447ad9f545c7f4ab5f307/wal-000000037 (ops 180-184)
I20260812 06:17:50.365765 29651 log.cc:1079] T 58c93dec2c1447ad9f545c7f4ab5f307 P 5cd7e80a980c4a4ea0b627a490207008: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/58c93dec2c1447ad9f545c7f4ab5f307/wal-000000038 (ops 185-189)
I20260812 06:17:50.390743 29651 maintenance_manager.cc:643] P 5cd7e80a980c4a4ea0b627a490207008: LogGCOp(58c93dec2c1447ad9f545c7f4ab5f307) complete. Timing: real 0.026s	user 0.002s	sys 0.023s Metrics: {}
I20260812 06:17:50.391180 29772 maintenance_manager.cc:419] P 5cd7e80a980c4a4ea0b627a490207008: Scheduling FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307): perf score=15.087375
I20260812 06:17:50.401659 29460 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.650s	user 1.699s	sys 0.154s
I20260812 06:17:50.429113 29460 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.027s	user 0.001s	sys 0.000s
I20260812 06:17:50.437597 29651 maintenance_manager.cc:643] P 5cd7e80a980c4a4ea0b627a490207008: FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307) complete. Timing: real 0.046s	user 0.022s	sys 0.021s Metrics: {"bytes_written":16820144,"delete_count":0,"lbm_write_time_us":16932,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:17:50.437708 29460 tablet_server.cc:179] TabletServer@127.28.197.1:0 shutting down...
I20260812 06:17:50.438228 29772 maintenance_manager.cc:419] P 5cd7e80a980c4a4ea0b627a490207008: Scheduling FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307): perf score=2.188937
I20260812 06:17:50.448975 29651 maintenance_manager.cc:643] P 5cd7e80a980c4a4ea0b627a490207008: FlushDeltaMemStoresOp(58c93dec2c1447ad9f545c7f4ab5f307) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4021,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:50.449419 29460 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:50.449785 29460 tablet_replica.cc:333] T 58c93dec2c1447ad9f545c7f4ab5f307 P 5cd7e80a980c4a4ea0b627a490207008: stopping tablet replica
I20260812 06:17:50.449971 29460 raft_consensus.cc:2243] T 58c93dec2c1447ad9f545c7f4ab5f307 P 5cd7e80a980c4a4ea0b627a490207008 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:50.450194 29460 raft_consensus.cc:2272] T 58c93dec2c1447ad9f545c7f4ab5f307 P 5cd7e80a980c4a4ea0b627a490207008 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:50.464264 29460 tablet_server.cc:196] TabletServer@127.28.197.1:0 shutdown complete.
I20260812 06:17:50.468317 29460 master.cc:562] Master@127.28.197.62:43723 shutting down...
I20260812 06:17:50.471354 29460 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 6b715049f77047c9b321f0787c917a60 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:50.471477 29460 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 6b715049f77047c9b321f0787c917a60 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:50.471526 29460 tablet_replica.cc:333] T 00000000000000000000000000000000 P 6b715049f77047c9b321f0787c917a60: stopping tablet replica
I20260812 06:17:50.483347 29460 master.cc:584] Master@127.28.197.62:43723 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5025 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:17:50.558681 29460 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.28.197.62:35081
I20260812 06:17:50.559026 29460 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:50.560909 29826 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:50.560969 29839 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:50.561136 29460 server_base.cc:1061] running on GCE node
W20260812 06:17:50.561216 29825 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:50.561425 29460 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:50.561466 29460 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:50.561501 29460 hybrid_clock.cc:648] HybridClock initialized: now 1786515470561500 us; error 0 us; skew 500 ppm
I20260812 06:17:50.562299 29460 webserver.cc:533] Webserver started at http://127.28.197.62:38359/ using document root <none> and password file <none>
I20260812 06:17:50.562459 29460 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:50.562503 29460 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:50.562577 29460 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:50.562933 29460 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465523567-29460-0/minicluster-data/master-0-root/instance:
uuid: "3c9fab2d7ea14600a12df726dd10a2de"
format_stamp: "Formatted at 2026-08-12 06:17:50 on dist-test-slave-q9h9"
I20260812 06:17:50.564363 29460 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:50.565188 29851 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:50.565395 29460 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:50.565466 29460 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465523567-29460-0/minicluster-data/master-0-root
uuid: "3c9fab2d7ea14600a12df726dd10a2de"
format_stamp: "Formatted at 2026-08-12 06:17:50 on dist-test-slave-q9h9"
I20260812 06:17:50.565533 29460 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465523567-29460-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465523567-29460-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465523567-29460-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:50.585436 29460 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:50.585752 29460 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:50.589468 29460 rpc_server.cc:307] RPC server started. Bound to: 127.28.197.62:35081
I20260812 06:17:50.596989 29948 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.28.197.62:35081 every 8 connection(s)
I20260812 06:17:50.597424 29949 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:50.599121 29949 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 3c9fab2d7ea14600a12df726dd10a2de: Bootstrap starting.
I20260812 06:17:50.599843 29949 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 3c9fab2d7ea14600a12df726dd10a2de: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:50.600765 29949 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 3c9fab2d7ea14600a12df726dd10a2de: No bootstrap required, opened a new log
I20260812 06:17:50.601130 29949 raft_consensus.cc:359] T 00000000000000000000000000000000 P 3c9fab2d7ea14600a12df726dd10a2de [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3c9fab2d7ea14600a12df726dd10a2de" member_type: VOTER }
I20260812 06:17:50.601226 29949 raft_consensus.cc:385] T 00000000000000000000000000000000 P 3c9fab2d7ea14600a12df726dd10a2de [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:50.601259 29949 raft_consensus.cc:740] T 00000000000000000000000000000000 P 3c9fab2d7ea14600a12df726dd10a2de [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 3c9fab2d7ea14600a12df726dd10a2de, State: Initialized, Role: FOLLOWER
I20260812 06:17:50.601400 29949 consensus_queue.cc:260] T 00000000000000000000000000000000 P 3c9fab2d7ea14600a12df726dd10a2de [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: "3c9fab2d7ea14600a12df726dd10a2de" member_type: VOTER }
I20260812 06:17:50.601471 29949 raft_consensus.cc:399] T 00000000000000000000000000000000 P 3c9fab2d7ea14600a12df726dd10a2de [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:50.601507 29949 raft_consensus.cc:493] T 00000000000000000000000000000000 P 3c9fab2d7ea14600a12df726dd10a2de [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:50.601555 29949 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 3c9fab2d7ea14600a12df726dd10a2de [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:50.602221 29949 raft_consensus.cc:515] T 00000000000000000000000000000000 P 3c9fab2d7ea14600a12df726dd10a2de [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3c9fab2d7ea14600a12df726dd10a2de" member_type: VOTER }
I20260812 06:17:50.602348 29949 leader_election.cc:304] T 00000000000000000000000000000000 P 3c9fab2d7ea14600a12df726dd10a2de [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: 3c9fab2d7ea14600a12df726dd10a2de; no voters: 
I20260812 06:17:50.602522 29949 leader_election.cc:290] T 00000000000000000000000000000000 P 3c9fab2d7ea14600a12df726dd10a2de [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:50.602627 29955 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 3c9fab2d7ea14600a12df726dd10a2de [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:50.602859 29955 raft_consensus.cc:697] T 00000000000000000000000000000000 P 3c9fab2d7ea14600a12df726dd10a2de [term 1 LEADER]: Becoming Leader. State: Replica: 3c9fab2d7ea14600a12df726dd10a2de, State: Running, Role: LEADER
I20260812 06:17:50.602914 29949 sys_catalog.cc:565] T 00000000000000000000000000000000 P 3c9fab2d7ea14600a12df726dd10a2de [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:50.602996 29955 consensus_queue.cc:237] T 00000000000000000000000000000000 P 3c9fab2d7ea14600a12df726dd10a2de [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: "3c9fab2d7ea14600a12df726dd10a2de" member_type: VOTER }
I20260812 06:17:50.603410 29956 sys_catalog.cc:455] T 00000000000000000000000000000000 P 3c9fab2d7ea14600a12df726dd10a2de [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "3c9fab2d7ea14600a12df726dd10a2de" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3c9fab2d7ea14600a12df726dd10a2de" member_type: VOTER } }
I20260812 06:17:50.603437 29958 sys_catalog.cc:455] T 00000000000000000000000000000000 P 3c9fab2d7ea14600a12df726dd10a2de [sys.catalog]: SysCatalogTable state changed. Reason: New leader 3c9fab2d7ea14600a12df726dd10a2de. Latest consensus state: current_term: 1 leader_uuid: "3c9fab2d7ea14600a12df726dd10a2de" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3c9fab2d7ea14600a12df726dd10a2de" member_type: VOTER } }
I20260812 06:17:50.603581 29958 sys_catalog.cc:458] T 00000000000000000000000000000000 P 3c9fab2d7ea14600a12df726dd10a2de [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:50.603835 29974 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:50.604050 29956 sys_catalog.cc:458] T 00000000000000000000000000000000 P 3c9fab2d7ea14600a12df726dd10a2de [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:50.604678 29974 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:50.604832 29460 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:50.606452 29974 catalog_manager.cc:1383] Generated new cluster ID: 9b9787b645b9409eb8d2ee8fd3a48888
I20260812 06:17:50.606509 29974 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:50.619310 29974 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:50.619804 29974 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:50.624814 29974 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 3c9fab2d7ea14600a12df726dd10a2de: Generated new TSK 0
I20260812 06:17:50.624959 29974 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:50.637004 29460 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:50.638760 29993 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:50.638792 29460 server_base.cc:1061] running on GCE node
W20260812 06:17:50.638929 30000 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:50.638928 29994 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:50.639215 29460 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:50.639273 29460 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:50.639294 29460 hybrid_clock.cc:648] HybridClock initialized: now 1786515470639294 us; error 0 us; skew 500 ppm
I20260812 06:17:50.640039 29460 webserver.cc:533] Webserver started at http://127.28.197.1:41915/ using document root <none> and password file <none>
I20260812 06:17:50.640182 29460 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:50.640240 29460 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:50.640319 29460 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:50.640661 29460 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465523567-29460-0/minicluster-data/ts-0-root/instance:
uuid: "859dcf640ba347adaa34ad374fecbf18"
format_stamp: "Formatted at 2026-08-12 06:17:50 on dist-test-slave-q9h9"
I20260812 06:17:50.642047 29460 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.001s
I20260812 06:17:50.642910 30012 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:50.643105 29460 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:17:50.643170 29460 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465523567-29460-0/minicluster-data/ts-0-root
uuid: "859dcf640ba347adaa34ad374fecbf18"
format_stamp: "Formatted at 2026-08-12 06:17:50 on dist-test-slave-q9h9"
I20260812 06:17:50.643244 29460 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465523567-29460-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465523567-29460-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465523567-29460-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:50.649988 29460 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:50.650301 29460 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:50.650547 29460 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:50.650943 29460 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:50.650980 29460 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:50.651019 29460 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:50.651048 29460 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:50.654935 29460 rpc_server.cc:307] RPC server started. Bound to: 127.28.197.1:46731
I20260812 06:17:50.655797 30130 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.28.197.1:46731 every 8 connection(s)
I20260812 06:17:50.659894 30131 heartbeater.cc:344] Connected to a master server at 127.28.197.62:35081
I20260812 06:17:50.660001 30131 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:50.660181 30131 heartbeater.cc:507] Master 127.28.197.62:35081 requested a full tablet report, sending...
I20260812 06:17:50.660768 29886 ts_manager.cc:194] Registered new tserver with Master: 859dcf640ba347adaa34ad374fecbf18 (127.28.197.1:46731)
I20260812 06:17:50.661152 29460 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.005481261s
I20260812 06:17:50.661476 29886 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:40982
I20260812 06:17:50.667515 29886 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:40990:
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:50.675451 30066 tablet_service.cc:1511] Processing CreateTablet for tablet 0fd0f4143f2343169fc3d394632a64cd (DEFAULT_TABLE table=heavy-update-compaction-test [id=6516c29a133e4bde81e9b1ce3d50d419]), partition=
I20260812 06:17:50.675678 30066 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 0fd0f4143f2343169fc3d394632a64cd. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:50.677390 30155 tablet_bootstrap.cc:492] T 0fd0f4143f2343169fc3d394632a64cd P 859dcf640ba347adaa34ad374fecbf18: Bootstrap starting.
I20260812 06:17:50.678372 30155 tablet_bootstrap.cc:654] T 0fd0f4143f2343169fc3d394632a64cd P 859dcf640ba347adaa34ad374fecbf18: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:50.679369 30155 tablet_bootstrap.cc:492] T 0fd0f4143f2343169fc3d394632a64cd P 859dcf640ba347adaa34ad374fecbf18: No bootstrap required, opened a new log
I20260812 06:17:50.679441 30155 ts_tablet_manager.cc:1403] T 0fd0f4143f2343169fc3d394632a64cd P 859dcf640ba347adaa34ad374fecbf18: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:50.679827 30155 raft_consensus.cc:359] T 0fd0f4143f2343169fc3d394632a64cd P 859dcf640ba347adaa34ad374fecbf18 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "859dcf640ba347adaa34ad374fecbf18" member_type: VOTER last_known_addr { host: "127.28.197.1" port: 46731 } }
I20260812 06:17:50.679911 30155 raft_consensus.cc:385] T 0fd0f4143f2343169fc3d394632a64cd P 859dcf640ba347adaa34ad374fecbf18 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:50.679939 30155 raft_consensus.cc:740] T 0fd0f4143f2343169fc3d394632a64cd P 859dcf640ba347adaa34ad374fecbf18 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 859dcf640ba347adaa34ad374fecbf18, State: Initialized, Role: FOLLOWER
I20260812 06:17:50.680084 30155 consensus_queue.cc:260] T 0fd0f4143f2343169fc3d394632a64cd P 859dcf640ba347adaa34ad374fecbf18 [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: "859dcf640ba347adaa34ad374fecbf18" member_type: VOTER last_known_addr { host: "127.28.197.1" port: 46731 } }
I20260812 06:17:50.680163 30155 raft_consensus.cc:399] T 0fd0f4143f2343169fc3d394632a64cd P 859dcf640ba347adaa34ad374fecbf18 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:50.680197 30155 raft_consensus.cc:493] T 0fd0f4143f2343169fc3d394632a64cd P 859dcf640ba347adaa34ad374fecbf18 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:50.680253 30155 raft_consensus.cc:3060] T 0fd0f4143f2343169fc3d394632a64cd P 859dcf640ba347adaa34ad374fecbf18 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:50.681041 30155 raft_consensus.cc:515] T 0fd0f4143f2343169fc3d394632a64cd P 859dcf640ba347adaa34ad374fecbf18 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "859dcf640ba347adaa34ad374fecbf18" member_type: VOTER last_known_addr { host: "127.28.197.1" port: 46731 } }
I20260812 06:17:50.681190 30155 leader_election.cc:304] T 0fd0f4143f2343169fc3d394632a64cd P 859dcf640ba347adaa34ad374fecbf18 [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: 859dcf640ba347adaa34ad374fecbf18; no voters: 
I20260812 06:17:50.681396 30155 leader_election.cc:290] T 0fd0f4143f2343169fc3d394632a64cd P 859dcf640ba347adaa34ad374fecbf18 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:50.681491 30159 raft_consensus.cc:2804] T 0fd0f4143f2343169fc3d394632a64cd P 859dcf640ba347adaa34ad374fecbf18 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:50.681668 30159 raft_consensus.cc:697] T 0fd0f4143f2343169fc3d394632a64cd P 859dcf640ba347adaa34ad374fecbf18 [term 1 LEADER]: Becoming Leader. State: Replica: 859dcf640ba347adaa34ad374fecbf18, State: Running, Role: LEADER
I20260812 06:17:50.681681 30155 ts_tablet_manager.cc:1434] T 0fd0f4143f2343169fc3d394632a64cd P 859dcf640ba347adaa34ad374fecbf18: Time spent starting tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:50.681741 30131 heartbeater.cc:499] Master 127.28.197.62:35081 was elected leader, sending a full tablet report...
I20260812 06:17:50.681823 30159 consensus_queue.cc:237] T 0fd0f4143f2343169fc3d394632a64cd P 859dcf640ba347adaa34ad374fecbf18 [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: "859dcf640ba347adaa34ad374fecbf18" member_type: VOTER last_known_addr { host: "127.28.197.1" port: 46731 } }
I20260812 06:17:50.683074 29886 catalog_manager.cc:5719] T 0fd0f4143f2343169fc3d394632a64cd P 859dcf640ba347adaa34ad374fecbf18 reported cstate change: term changed from 0 to 1, leader changed from <none> to 859dcf640ba347adaa34ad374fecbf18 (127.28.197.1). New cstate: current_term: 1 leader_uuid: "859dcf640ba347adaa34ad374fecbf18" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "859dcf640ba347adaa34ad374fecbf18" member_type: VOTER last_known_addr { host: "127.28.197.1" port: 46731 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:50.736083 29460 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.050s	user 0.015s	sys 0.006s
I20260812 06:17:50.906288 30132 maintenance_manager.cc:419] P 859dcf640ba347adaa34ad374fecbf18: Scheduling FlushMRSOp(0fd0f4143f2343169fc3d394632a64cd): perf score=23.023690
I20260812 06:17:51.071116 30021 maintenance_manager.cc:643] P 859dcf640ba347adaa34ad374fecbf18: FlushMRSOp(0fd0f4143f2343169fc3d394632a64cd) complete. Timing: real 0.165s	user 0.121s	sys 0.036s Metrics: {"bytes_written":14235624,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":71,"dirs.run_cpu_time_us":202,"dirs.run_wall_time_us":790,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":43873,"lbm_writes_lt_1ms":904,"mutex_wait_us":807,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"spinlock_wait_cycles":15488,"update_count":1735}
I20260812 06:17:51.071736 30132 maintenance_manager.cc:419] P 859dcf640ba347adaa34ad374fecbf18: Scheduling FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd): perf score=1.196750
I20260812 06:17:51.085697 30021 maintenance_manager.cc:643] P 859dcf640ba347adaa34ad374fecbf18: FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd) complete. Timing: real 0.014s	user 0.001s	sys 0.005s Metrics: {"bytes_written":2912938,"delete_count":0,"lbm_write_time_us":2784,"lbm_writes_lt_1ms":74,"reinsert_count":0,"update_count":355}
I20260812 06:17:51.086103 30132 maintenance_manager.cc:419] P 859dcf640ba347adaa34ad374fecbf18: Scheduling LogGCOp(0fd0f4143f2343169fc3d394632a64cd): free 20290830 bytes of WAL
I20260812 06:17:51.086287 30021 log_reader.cc:385] T 0fd0f4143f2343169fc3d394632a64cd: removed 2 log segments from log reader
I20260812 06:17:51.086330 30021 log.cc:1079] T 0fd0f4143f2343169fc3d394632a64cd P 859dcf640ba347adaa34ad374fecbf18: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/0fd0f4143f2343169fc3d394632a64cd/wal-000000001 (ops 1-6)
I20260812 06:17:51.086367 30021 log.cc:1079] T 0fd0f4143f2343169fc3d394632a64cd P 859dcf640ba347adaa34ad374fecbf18: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/0fd0f4143f2343169fc3d394632a64cd/wal-000000002 (ops 7-10)
I20260812 06:17:51.089882 30021 maintenance_manager.cc:643] P 859dcf640ba347adaa34ad374fecbf18: LogGCOp(0fd0f4143f2343169fc3d394632a64cd) complete. Timing: real 0.004s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:17:51.090178 30132 maintenance_manager.cc:419] P 859dcf640ba347adaa34ad374fecbf18: Scheduling UndoDeltaBlockGCOp(0fd0f4143f2343169fc3d394632a64cd): 20513814 bytes on disk
I20260812 06:17:51.090510 30021 maintenance_manager.cc:643] P 859dcf640ba347adaa34ad374fecbf18: UndoDeltaBlockGCOp(0fd0f4143f2343169fc3d394632a64cd) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4}
I20260812 06:17:51.090866 30132 maintenance_manager.cc:419] P 859dcf640ba347adaa34ad374fecbf18: Scheduling FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd): perf score=2.188937
I20260812 06:17:51.099180 30021 maintenance_manager.cc:643] P 859dcf640ba347adaa34ad374fecbf18: FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd) complete. Timing: real 0.008s	user 0.006s	sys 0.001s Metrics: {"bytes_written":3364205,"delete_count":0,"lbm_write_time_us":3017,"lbm_writes_lt_1ms":85,"reinsert_count":0,"update_count":410}
I20260812 06:17:51.099627 30132 maintenance_manager.cc:419] P 859dcf640ba347adaa34ad374fecbf18: Scheduling MajorDeltaCompactionOp(0fd0f4143f2343169fc3d394632a64cd): perf score=1.000000
I20260812 06:17:51.261510 30021 maintenance_manager.cc:643] P 859dcf640ba347adaa34ad374fecbf18: MajorDeltaCompactionOp(0fd0f4143f2343169fc3d394632a64cd) complete. Timing: real 0.162s	user 0.115s	sys 0.040s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815762,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":431,"lbm_read_time_us":13291,"lbm_reads_lt_1ms":569,"lbm_write_time_us":26441,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"thread_start_us":245,"threads_started":5,"update_count":2500}
I20260812 06:17:51.261936 30132 maintenance_manager.cc:419] P 859dcf640ba347adaa34ad374fecbf18: Scheduling FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd): perf score=14.095187
I20260812 06:17:51.318174 30021 maintenance_manager.cc:643] P 859dcf640ba347adaa34ad374fecbf18: FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd) complete. Timing: real 0.056s	user 0.034s	sys 0.013s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20727,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:51.318653 30132 maintenance_manager.cc:419] P 859dcf640ba347adaa34ad374fecbf18: Scheduling FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd): perf score=2.188937
I20260812 06:17:51.328346 30021 maintenance_manager.cc:643] P 859dcf640ba347adaa34ad374fecbf18: FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3720,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:51.328785 30132 maintenance_manager.cc:419] P 859dcf640ba347adaa34ad374fecbf18: Scheduling MajorDeltaCompactionOp(0fd0f4143f2343169fc3d394632a64cd): perf score=1.000000
I20260812 06:17:51.503826 30021 maintenance_manager.cc:643] P 859dcf640ba347adaa34ad374fecbf18: MajorDeltaCompactionOp(0fd0f4143f2343169fc3d394632a64cd) complete. Timing: real 0.175s	user 0.111s	sys 0.064s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":161,"lbm_read_time_us":14240,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27515,"lbm_writes_lt_1ms":543,"mutex_wait_us":49,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":58240,"update_count":2500}
I20260812 06:17:51.504299 30132 maintenance_manager.cc:419] P 859dcf640ba347adaa34ad374fecbf18: Scheduling FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd): perf score=14.095187
I20260812 06:17:51.542654 30021 maintenance_manager.cc:643] P 859dcf640ba347adaa34ad374fecbf18: FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd) complete. Timing: real 0.038s	user 0.026s	sys 0.012s Metrics: {"bytes_written":16409899,"delete_count":0,"lbm_write_time_us":17234,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:51.543262 30132 maintenance_manager.cc:419] P 859dcf640ba347adaa34ad374fecbf18: Scheduling MajorDeltaCompactionOp(0fd0f4143f2343169fc3d394632a64cd): perf score=1.000000
I20260812 06:17:51.707631 30021 maintenance_manager.cc:643] P 859dcf640ba347adaa34ad374fecbf18: MajorDeltaCompactionOp(0fd0f4143f2343169fc3d394632a64cd) complete. Timing: real 0.164s	user 0.108s	sys 0.045s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713150,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":555,"lbm_read_time_us":12107,"lbm_reads_lt_1ms":467,"lbm_write_time_us":25593,"lbm_writes_lt_1ms":443,"mutex_wait_us":22,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9344,"update_count":2000}
I20260812 06:17:51.708158 30132 maintenance_manager.cc:419] P 859dcf640ba347adaa34ad374fecbf18: Scheduling FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd): perf score=14.095187
I20260812 06:17:51.752820 30021 maintenance_manager.cc:643] P 859dcf640ba347adaa34ad374fecbf18: FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd) complete. Timing: real 0.045s	user 0.034s	sys 0.004s Metrics: {"bytes_written":16409899,"delete_count":0,"lbm_write_time_us":18333,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:51.753228 30132 maintenance_manager.cc:419] P 859dcf640ba347adaa34ad374fecbf18: Scheduling FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd): perf score=2.188937
I20260812 06:17:51.763577 30021 maintenance_manager.cc:643] P 859dcf640ba347adaa34ad374fecbf18: FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3855,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:51.764119 30132 maintenance_manager.cc:419] P 859dcf640ba347adaa34ad374fecbf18: Scheduling MajorDeltaCompactionOp(0fd0f4143f2343169fc3d394632a64cd): perf score=1.000000
I20260812 06:17:51.947918 30021 maintenance_manager.cc:643] P 859dcf640ba347adaa34ad374fecbf18: MajorDeltaCompactionOp(0fd0f4143f2343169fc3d394632a64cd) complete. Timing: real 0.184s	user 0.117s	sys 0.055s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815681,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":91,"lbm_read_time_us":11799,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27161,"lbm_writes_lt_1ms":543,"mutex_wait_us":38,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3968,"update_count":2500}
I20260812 06:17:51.948378 30132 maintenance_manager.cc:419] P 859dcf640ba347adaa34ad374fecbf18: Scheduling FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd): perf score=14.095187
I20260812 06:17:51.999053 30021 maintenance_manager.cc:643] P 859dcf640ba347adaa34ad374fecbf18: FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd) complete. Timing: real 0.051s	user 0.026s	sys 0.015s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18775,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:51.999589 30132 maintenance_manager.cc:419] P 859dcf640ba347adaa34ad374fecbf18: Scheduling FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd): perf score=2.188937
I20260812 06:17:52.010099 30021 maintenance_manager.cc:643] P 859dcf640ba347adaa34ad374fecbf18: FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd) complete. Timing: real 0.010s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3924,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:52.010538 30132 maintenance_manager.cc:419] P 859dcf640ba347adaa34ad374fecbf18: Scheduling MajorDeltaCompactionOp(0fd0f4143f2343169fc3d394632a64cd): perf score=1.000000
I20260812 06:17:52.167536 30021 maintenance_manager.cc:643] P 859dcf640ba347adaa34ad374fecbf18: MajorDeltaCompactionOp(0fd0f4143f2343169fc3d394632a64cd) complete. Timing: real 0.157s	user 0.100s	sys 0.053s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":91,"lbm_read_time_us":10119,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30494,"lbm_writes_lt_1ms":543,"mutex_wait_us":45,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4224,"update_count":2500}
I20260812 06:17:52.168013 30132 maintenance_manager.cc:419] P 859dcf640ba347adaa34ad374fecbf18: Scheduling FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd): perf score=11.118625
I20260812 06:17:52.202212 30021 maintenance_manager.cc:643] P 859dcf640ba347adaa34ad374fecbf18: FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd) complete. Timing: real 0.034s	user 0.021s	sys 0.013s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":14500,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:52.202816 30132 maintenance_manager.cc:419] P 859dcf640ba347adaa34ad374fecbf18: Scheduling FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd): perf score=2.188937
I20260812 06:17:52.218997 30021 maintenance_manager.cc:643] P 859dcf640ba347adaa34ad374fecbf18: FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd) complete. Timing: real 0.016s	user 0.007s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4759,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:52.219487 30132 maintenance_manager.cc:419] P 859dcf640ba347adaa34ad374fecbf18: Scheduling FlushMRSOp(0fd0f4143f2343169fc3d394632a64cd): perf score=1.000000
I20260812 06:17:52.256487 30021 maintenance_manager.cc:643] P 859dcf640ba347adaa34ad374fecbf18: FlushMRSOp(0fd0f4143f2343169fc3d394632a64cd) complete. Timing: real 0.037s	user 0.021s	sys 0.004s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":67,"dirs.run_cpu_time_us":165,"dirs.run_wall_time_us":952,"drs_written":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2006,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:52.257100 30132 maintenance_manager.cc:419] P 859dcf640ba347adaa34ad374fecbf18: Scheduling UndoDeltaBlockGCOp(0fd0f4143f2343169fc3d394632a64cd): 462 bytes on disk
I20260812 06:17:52.257537 30021 maintenance_manager.cc:643] P 859dcf640ba347adaa34ad374fecbf18: UndoDeltaBlockGCOp(0fd0f4143f2343169fc3d394632a64cd) 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:52.258122 30132 maintenance_manager.cc:419] P 859dcf640ba347adaa34ad374fecbf18: Scheduling FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd): perf score=3.181125
I20260812 06:17:52.270748 30021 maintenance_manager.cc:643] P 859dcf640ba347adaa34ad374fecbf18: FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd) complete. Timing: real 0.012s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4102,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:52.271129 30132 maintenance_manager.cc:419] P 859dcf640ba347adaa34ad374fecbf18: Scheduling LogGCOp(0fd0f4143f2343169fc3d394632a64cd): free 117302576 bytes of WAL
I20260812 06:17:52.271332 30021 log_reader.cc:385] T 0fd0f4143f2343169fc3d394632a64cd: removed 12 log segments from log reader
I20260812 06:17:52.271373 30021 log.cc:1079] T 0fd0f4143f2343169fc3d394632a64cd P 859dcf640ba347adaa34ad374fecbf18: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/0fd0f4143f2343169fc3d394632a64cd/wal-000000003 (ops 11-15)
I20260812 06:17:52.271401 30021 log.cc:1079] T 0fd0f4143f2343169fc3d394632a64cd P 859dcf640ba347adaa34ad374fecbf18: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/0fd0f4143f2343169fc3d394632a64cd/wal-000000004 (ops 16-20)
I20260812 06:17:52.271435 30021 log.cc:1079] T 0fd0f4143f2343169fc3d394632a64cd P 859dcf640ba347adaa34ad374fecbf18: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/0fd0f4143f2343169fc3d394632a64cd/wal-000000005 (ops 21-25)
I20260812 06:17:52.271467 30021 log.cc:1079] T 0fd0f4143f2343169fc3d394632a64cd P 859dcf640ba347adaa34ad374fecbf18: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/0fd0f4143f2343169fc3d394632a64cd/wal-000000006 (ops 26-30)
I20260812 06:17:52.271498 30021 log.cc:1079] T 0fd0f4143f2343169fc3d394632a64cd P 859dcf640ba347adaa34ad374fecbf18: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/0fd0f4143f2343169fc3d394632a64cd/wal-000000007 (ops 31-35)
I20260812 06:17:52.271529 30021 log.cc:1079] T 0fd0f4143f2343169fc3d394632a64cd P 859dcf640ba347adaa34ad374fecbf18: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/0fd0f4143f2343169fc3d394632a64cd/wal-000000008 (ops 36-40)
I20260812 06:17:52.271561 30021 log.cc:1079] T 0fd0f4143f2343169fc3d394632a64cd P 859dcf640ba347adaa34ad374fecbf18: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/0fd0f4143f2343169fc3d394632a64cd/wal-000000009 (ops 41-44)
I20260812 06:17:52.271592 30021 log.cc:1079] T 0fd0f4143f2343169fc3d394632a64cd P 859dcf640ba347adaa34ad374fecbf18: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/0fd0f4143f2343169fc3d394632a64cd/wal-000000010 (ops 45-49)
I20260812 06:17:52.271623 30021 log.cc:1079] T 0fd0f4143f2343169fc3d394632a64cd P 859dcf640ba347adaa34ad374fecbf18: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/0fd0f4143f2343169fc3d394632a64cd/wal-000000011 (ops 50-54)
I20260812 06:17:52.271653 30021 log.cc:1079] T 0fd0f4143f2343169fc3d394632a64cd P 859dcf640ba347adaa34ad374fecbf18: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/0fd0f4143f2343169fc3d394632a64cd/wal-000000012 (ops 55-58)
I20260812 06:17:52.271684 30021 log.cc:1079] T 0fd0f4143f2343169fc3d394632a64cd P 859dcf640ba347adaa34ad374fecbf18: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/0fd0f4143f2343169fc3d394632a64cd/wal-000000013 (ops 59-63)
I20260812 06:17:52.271716 30021 log.cc:1079] T 0fd0f4143f2343169fc3d394632a64cd P 859dcf640ba347adaa34ad374fecbf18: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/0fd0f4143f2343169fc3d394632a64cd/wal-000000014 (ops 64-68)
I20260812 06:17:52.293682 30021 maintenance_manager.cc:643] P 859dcf640ba347adaa34ad374fecbf18: LogGCOp(0fd0f4143f2343169fc3d394632a64cd) complete. Timing: real 0.022s	user 0.000s	sys 0.019s Metrics: {}
I20260812 06:17:52.294104 30132 maintenance_manager.cc:419] P 859dcf640ba347adaa34ad374fecbf18: Scheduling FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd): perf score=2.188937
I20260812 06:17:52.318908 30021 maintenance_manager.cc:643] P 859dcf640ba347adaa34ad374fecbf18: FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd) complete. Timing: real 0.025s	user 0.008s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3635,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:52.319415 30132 maintenance_manager.cc:419] P 859dcf640ba347adaa34ad374fecbf18: Scheduling LogGCOp(0fd0f4143f2343169fc3d394632a64cd): free 11564875 bytes of WAL
I20260812 06:17:52.319629 30021 log_reader.cc:385] T 0fd0f4143f2343169fc3d394632a64cd: removed 1 log segments from log reader
I20260812 06:17:52.319679 30021 log.cc:1079] T 0fd0f4143f2343169fc3d394632a64cd P 859dcf640ba347adaa34ad374fecbf18: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/0fd0f4143f2343169fc3d394632a64cd/wal-000000015 (ops 69-72)
I20260812 06:17:52.321614 30021 maintenance_manager.cc:643] P 859dcf640ba347adaa34ad374fecbf18: LogGCOp(0fd0f4143f2343169fc3d394632a64cd) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:17:52.321902 30132 maintenance_manager.cc:419] P 859dcf640ba347adaa34ad374fecbf18: Scheduling FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd): perf score=2.188937
I20260812 06:17:52.331065 30021 maintenance_manager.cc:643] P 859dcf640ba347adaa34ad374fecbf18: FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd) complete. Timing: real 0.009s	user 0.005s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3353,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:52.331457 30132 maintenance_manager.cc:419] P 859dcf640ba347adaa34ad374fecbf18: Scheduling MajorDeltaCompactionOp(0fd0f4143f2343169fc3d394632a64cd): perf score=1.000000
I20260812 06:17:52.561192 30021 maintenance_manager.cc:643] P 859dcf640ba347adaa34ad374fecbf18: MajorDeltaCompactionOp(0fd0f4143f2343169fc3d394632a64cd) complete. Timing: real 0.230s	user 0.149s	sys 0.069s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":33020847,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":2669,"lbm_read_time_us":15264,"lbm_reads_lt_1ms":775,"lbm_write_time_us":33491,"lbm_writes_lt_1ms":743,"mutex_wait_us":2046,"peak_mem_usage":87969044,"reinsert_count":0,"thread_start_us":78,"threads_started":1,"update_count":3500}
I20260812 06:17:52.561720 30132 maintenance_manager.cc:419] P 859dcf640ba347adaa34ad374fecbf18: Scheduling FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd): perf score=18.063937
I20260812 06:17:52.620239 30021 maintenance_manager.cc:643] P 859dcf640ba347adaa34ad374fecbf18: FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd) complete. Timing: real 0.058s	user 0.033s	sys 0.012s Metrics: {"bytes_written":20512318,"delete_count":0,"lbm_write_time_us":21270,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:52.620777 30132 maintenance_manager.cc:419] P 859dcf640ba347adaa34ad374fecbf18: Scheduling FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd): perf score=2.188937
I20260812 06:17:52.630666 30021 maintenance_manager.cc:643] P 859dcf640ba347adaa34ad374fecbf18: FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3797,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:52.631227 30132 maintenance_manager.cc:419] P 859dcf640ba347adaa34ad374fecbf18: Scheduling MajorDeltaCompactionOp(0fd0f4143f2343169fc3d394632a64cd): perf score=1.000000
I20260812 06:17:52.837920 30021 maintenance_manager.cc:643] P 859dcf640ba347adaa34ad374fecbf18: MajorDeltaCompactionOp(0fd0f4143f2343169fc3d394632a64cd) complete. Timing: real 0.206s	user 0.122s	sys 0.084s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918100,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":339,"lbm_read_time_us":15315,"lbm_reads_lt_1ms":672,"lbm_write_time_us":34330,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":12544,"update_count":3000}
I20260812 06:17:52.841751 30132 maintenance_manager.cc:419] P 859dcf640ba347adaa34ad374fecbf18: Scheduling FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd): perf score=15.087375
I20260812 06:17:52.886874 30021 maintenance_manager.cc:643] P 859dcf640ba347adaa34ad374fecbf18: FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd) complete. Timing: real 0.045s	user 0.020s	sys 0.019s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":17315,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:17:52.887301 30132 maintenance_manager.cc:419] P 859dcf640ba347adaa34ad374fecbf18: Scheduling FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd): perf score=2.188937
I20260812 06:17:52.897630 30021 maintenance_manager.cc:643] P 859dcf640ba347adaa34ad374fecbf18: FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3844,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:52.898126 30132 maintenance_manager.cc:419] P 859dcf640ba347adaa34ad374fecbf18: Scheduling FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd): perf score=2.188937
I20260812 06:17:52.911158 30021 maintenance_manager.cc:643] P 859dcf640ba347adaa34ad374fecbf18: FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd) complete. Timing: real 0.013s	user 0.006s	sys 0.006s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5194,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:52.911545 30132 maintenance_manager.cc:419] P 859dcf640ba347adaa34ad374fecbf18: Scheduling MajorDeltaCompactionOp(0fd0f4143f2343169fc3d394632a64cd): perf score=1.000000
I20260812 06:17:53.118139 30021 maintenance_manager.cc:643] P 859dcf640ba347adaa34ad374fecbf18: MajorDeltaCompactionOp(0fd0f4143f2343169fc3d394632a64cd) complete. Timing: real 0.206s	user 0.124s	sys 0.082s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918201,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":227,"lbm_read_time_us":15005,"lbm_reads_lt_1ms":673,"lbm_write_time_us":32950,"lbm_writes_lt_1ms":643,"mutex_wait_us":55,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3200,"update_count":3000}
I20260812 06:17:53.118757 30132 maintenance_manager.cc:419] P 859dcf640ba347adaa34ad374fecbf18: Scheduling FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd): perf score=14.095187
I20260812 06:17:53.163470 30021 maintenance_manager.cc:643] P 859dcf640ba347adaa34ad374fecbf18: FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd) complete. Timing: real 0.045s	user 0.027s	sys 0.016s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":19328,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:53.164026 30132 maintenance_manager.cc:419] P 859dcf640ba347adaa34ad374fecbf18: Scheduling FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd): perf score=2.188937
I20260812 06:17:53.189476 30021 maintenance_manager.cc:643] P 859dcf640ba347adaa34ad374fecbf18: FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd) complete. Timing: real 0.025s	user 0.011s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6331,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:53.189937 30132 maintenance_manager.cc:419] P 859dcf640ba347adaa34ad374fecbf18: Scheduling FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd): perf score=2.188937
I20260812 06:17:53.199267 30021 maintenance_manager.cc:643] P 859dcf640ba347adaa34ad374fecbf18: FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd) complete. Timing: real 0.009s	user 0.002s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3617,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:53.199738 30132 maintenance_manager.cc:419] P 859dcf640ba347adaa34ad374fecbf18: Scheduling MajorDeltaCompactionOp(0fd0f4143f2343169fc3d394632a64cd): perf score=1.000000
I20260812 06:17:53.394205 30021 maintenance_manager.cc:643] P 859dcf640ba347adaa34ad374fecbf18: MajorDeltaCompactionOp(0fd0f4143f2343169fc3d394632a64cd) complete. Timing: real 0.194s	user 0.111s	sys 0.078s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918216,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":293,"lbm_read_time_us":14080,"lbm_reads_lt_1ms":673,"lbm_write_time_us":30593,"lbm_writes_lt_1ms":643,"mutex_wait_us":52,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":663424,"update_count":3000}
I20260812 06:17:53.394721 30132 maintenance_manager.cc:419] P 859dcf640ba347adaa34ad374fecbf18: Scheduling FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd): perf score=16.079562
I20260812 06:17:53.456593 30021 maintenance_manager.cc:643] P 859dcf640ba347adaa34ad374fecbf18: FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd) complete. Timing: real 0.062s	user 0.034s	sys 0.016s Metrics: {"bytes_written":18214959,"delete_count":0,"lbm_write_time_us":22765,"lbm_writes_lt_1ms":447,"reinsert_count":0,"update_count":2220}
I20260812 06:17:53.457058 30132 maintenance_manager.cc:419] P 859dcf640ba347adaa34ad374fecbf18: Scheduling FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd): perf score=5.165500
I20260812 06:17:53.479815 30021 maintenance_manager.cc:643] P 859dcf640ba347adaa34ad374fecbf18: FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd) complete. Timing: real 0.023s	user 0.009s	sys 0.012s Metrics: {"bytes_written":6400022,"delete_count":0,"lbm_write_time_us":8953,"lbm_writes_lt_1ms":159,"reinsert_count":0,"update_count":780}
I20260812 06:17:53.480525 30132 maintenance_manager.cc:419] P 859dcf640ba347adaa34ad374fecbf18: Scheduling MajorDeltaCompactionOp(0fd0f4143f2343169fc3d394632a64cd): perf score=1.000000
I20260812 06:17:53.680025 30021 maintenance_manager.cc:643] P 859dcf640ba347adaa34ad374fecbf18: MajorDeltaCompactionOp(0fd0f4143f2343169fc3d394632a64cd) complete. Timing: real 0.199s	user 0.122s	sys 0.072s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918098,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":293,"lbm_read_time_us":12772,"lbm_reads_lt_1ms":664,"lbm_write_time_us":32933,"lbm_writes_lt_1ms":643,"mutex_wait_us":16,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":13696,"update_count":3000}
I20260812 06:17:53.680581 30132 maintenance_manager.cc:419] P 859dcf640ba347adaa34ad374fecbf18: Scheduling FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd): perf score=18.063937
I20260812 06:17:53.737278 30021 maintenance_manager.cc:643] P 859dcf640ba347adaa34ad374fecbf18: FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd) complete. Timing: real 0.057s	user 0.028s	sys 0.020s Metrics: {"bytes_written":20512318,"delete_count":0,"lbm_write_time_us":22808,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:53.737722 30132 maintenance_manager.cc:419] P 859dcf640ba347adaa34ad374fecbf18: Scheduling FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd): perf score=2.188937
I20260812 06:17:53.747941 30021 maintenance_manager.cc:643] P 859dcf640ba347adaa34ad374fecbf18: FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3644,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:53.748380 30132 maintenance_manager.cc:419] P 859dcf640ba347adaa34ad374fecbf18: Scheduling FlushMRSOp(0fd0f4143f2343169fc3d394632a64cd): perf score=1.000000
I20260812 06:17:53.777966 30021 maintenance_manager.cc:643] P 859dcf640ba347adaa34ad374fecbf18: FlushMRSOp(0fd0f4143f2343169fc3d394632a64cd) complete. Timing: real 0.029s	user 0.023s	sys 0.005s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":46,"dirs.run_cpu_time_us":162,"dirs.run_wall_time_us":1022,"drs_written":1,"lbm_read_time_us":41,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1615,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:17:53.778591 30132 maintenance_manager.cc:419] P 859dcf640ba347adaa34ad374fecbf18: Scheduling LogGCOp(0fd0f4143f2343169fc3d394632a64cd): free 121459513 bytes of WAL
I20260812 06:17:53.778772 30021 log_reader.cc:385] T 0fd0f4143f2343169fc3d394632a64cd: removed 12 log segments from log reader
I20260812 06:17:53.778813 30021 log.cc:1079] T 0fd0f4143f2343169fc3d394632a64cd P 859dcf640ba347adaa34ad374fecbf18: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/0fd0f4143f2343169fc3d394632a64cd/wal-000000016 (ops 73-77)
I20260812 06:17:53.778851 30021 log.cc:1079] T 0fd0f4143f2343169fc3d394632a64cd P 859dcf640ba347adaa34ad374fecbf18: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/0fd0f4143f2343169fc3d394632a64cd/wal-000000017 (ops 78-82)
I20260812 06:17:53.778882 30021 log.cc:1079] T 0fd0f4143f2343169fc3d394632a64cd P 859dcf640ba347adaa34ad374fecbf18: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/0fd0f4143f2343169fc3d394632a64cd/wal-000000018 (ops 83-87)
I20260812 06:17:53.778915 30021 log.cc:1079] T 0fd0f4143f2343169fc3d394632a64cd P 859dcf640ba347adaa34ad374fecbf18: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/0fd0f4143f2343169fc3d394632a64cd/wal-000000019 (ops 88-92)
I20260812 06:17:53.778945 30021 log.cc:1079] T 0fd0f4143f2343169fc3d394632a64cd P 859dcf640ba347adaa34ad374fecbf18: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/0fd0f4143f2343169fc3d394632a64cd/wal-000000020 (ops 93-97)
I20260812 06:17:53.778975 30021 log.cc:1079] T 0fd0f4143f2343169fc3d394632a64cd P 859dcf640ba347adaa34ad374fecbf18: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/0fd0f4143f2343169fc3d394632a64cd/wal-000000021 (ops 98-102)
I20260812 06:17:53.779006 30021 log.cc:1079] T 0fd0f4143f2343169fc3d394632a64cd P 859dcf640ba347adaa34ad374fecbf18: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/0fd0f4143f2343169fc3d394632a64cd/wal-000000022 (ops 103-107)
I20260812 06:17:53.779035 30021 log.cc:1079] T 0fd0f4143f2343169fc3d394632a64cd P 859dcf640ba347adaa34ad374fecbf18: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/0fd0f4143f2343169fc3d394632a64cd/wal-000000023 (ops 108-112)
I20260812 06:17:53.779065 30021 log.cc:1079] T 0fd0f4143f2343169fc3d394632a64cd P 859dcf640ba347adaa34ad374fecbf18: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/0fd0f4143f2343169fc3d394632a64cd/wal-000000024 (ops 113-117)
I20260812 06:17:53.779105 30021 log.cc:1079] T 0fd0f4143f2343169fc3d394632a64cd P 859dcf640ba347adaa34ad374fecbf18: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/0fd0f4143f2343169fc3d394632a64cd/wal-000000025 (ops 118-122)
I20260812 06:17:53.779135 30021 log.cc:1079] T 0fd0f4143f2343169fc3d394632a64cd P 859dcf640ba347adaa34ad374fecbf18: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/0fd0f4143f2343169fc3d394632a64cd/wal-000000026 (ops 123-127)
I20260812 06:17:53.779165 30021 log.cc:1079] T 0fd0f4143f2343169fc3d394632a64cd P 859dcf640ba347adaa34ad374fecbf18: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/0fd0f4143f2343169fc3d394632a64cd/wal-000000027 (ops 128-132)
I20260812 06:17:53.803268 30021 maintenance_manager.cc:643] P 859dcf640ba347adaa34ad374fecbf18: LogGCOp(0fd0f4143f2343169fc3d394632a64cd) complete. Timing: real 0.025s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:17:53.803706 30132 maintenance_manager.cc:419] P 859dcf640ba347adaa34ad374fecbf18: Scheduling FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd): perf score=3.181125
I20260812 06:17:53.820768 30021 maintenance_manager.cc:643] P 859dcf640ba347adaa34ad374fecbf18: FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd) complete. Timing: real 0.017s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4800077,"delete_count":0,"lbm_write_time_us":7063,"lbm_writes_lt_1ms":120,"reinsert_count":0,"update_count":585}
I20260812 06:17:53.821192 30132 maintenance_manager.cc:419] P 859dcf640ba347adaa34ad374fecbf18: Scheduling LogGCOp(0fd0f4143f2343169fc3d394632a64cd): free 11564893 bytes of WAL
I20260812 06:17:53.821394 30021 log_reader.cc:385] T 0fd0f4143f2343169fc3d394632a64cd: removed 1 log segments from log reader
I20260812 06:17:53.821441 30021 log.cc:1079] T 0fd0f4143f2343169fc3d394632a64cd P 859dcf640ba347adaa34ad374fecbf18: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/0fd0f4143f2343169fc3d394632a64cd/wal-000000028 (ops 133-136)
I20260812 06:17:53.823347 30021 maintenance_manager.cc:643] P 859dcf640ba347adaa34ad374fecbf18: LogGCOp(0fd0f4143f2343169fc3d394632a64cd) complete. Timing: real 0.002s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:17:53.823653 30132 maintenance_manager.cc:419] P 859dcf640ba347adaa34ad374fecbf18: Scheduling FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd): perf score=2.188937
I20260812 06:17:53.832778 30021 maintenance_manager.cc:643] P 859dcf640ba347adaa34ad374fecbf18: FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd) complete. Timing: real 0.009s	user 0.003s	sys 0.005s Metrics: {"bytes_written":3405230,"delete_count":0,"lbm_write_time_us":3236,"lbm_writes_lt_1ms":86,"reinsert_count":0,"update_count":415}
I20260812 06:17:53.833257 30132 maintenance_manager.cc:419] P 859dcf640ba347adaa34ad374fecbf18: Scheduling UndoDeltaBlockGCOp(0fd0f4143f2343169fc3d394632a64cd): 493 bytes on disk
I20260812 06:17:53.833595 30021 maintenance_manager.cc:643] P 859dcf640ba347adaa34ad374fecbf18: UndoDeltaBlockGCOp(0fd0f4143f2343169fc3d394632a64cd) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4}
I20260812 06:17:53.834097 30132 maintenance_manager.cc:419] P 859dcf640ba347adaa34ad374fecbf18: Scheduling MajorDeltaCompactionOp(0fd0f4143f2343169fc3d394632a64cd): perf score=1.000000
I20260812 06:17:54.067955 30021 maintenance_manager.cc:643] P 859dcf640ba347adaa34ad374fecbf18: MajorDeltaCompactionOp(0fd0f4143f2343169fc3d394632a64cd) complete. Timing: real 0.234s	user 0.124s	sys 0.109s Metrics: {"cfile_cache_miss":834,"cfile_cache_miss_bytes":37123151,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":635,"lbm_read_time_us":18004,"lbm_reads_lt_1ms":874,"lbm_write_time_us":43497,"lbm_writes_lt_1ms":843,"mutex_wait_us":320,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":27392,"thread_start_us":71,"threads_started":1,"update_count":4000}
I20260812 06:17:54.068496 30132 maintenance_manager.cc:419] P 859dcf640ba347adaa34ad374fecbf18: Scheduling FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd): perf score=18.063937
I20260812 06:17:54.121534 30021 maintenance_manager.cc:643] P 859dcf640ba347adaa34ad374fecbf18: FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd) complete. Timing: real 0.053s	user 0.026s	sys 0.020s Metrics: {"bytes_written":20512318,"delete_count":0,"lbm_write_time_us":22158,"lbm_writes_lt_1ms":503,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2500}
I20260812 06:17:54.122063 30132 maintenance_manager.cc:419] P 859dcf640ba347adaa34ad374fecbf18: Scheduling FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd): perf score=3.181125
I20260812 06:17:54.140412 30021 maintenance_manager.cc:643] P 859dcf640ba347adaa34ad374fecbf18: FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd) complete. Timing: real 0.018s	user 0.014s	sys 0.001s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":6743,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:54.140892 30132 maintenance_manager.cc:419] P 859dcf640ba347adaa34ad374fecbf18: Scheduling FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd): perf score=2.188937
I20260812 06:17:54.149914 30021 maintenance_manager.cc:643] P 859dcf640ba347adaa34ad374fecbf18: FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd) complete. Timing: real 0.009s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3560,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:54.150286 30132 maintenance_manager.cc:419] P 859dcf640ba347adaa34ad374fecbf18: Scheduling MajorDeltaCompactionOp(0fd0f4143f2343169fc3d394632a64cd): perf score=1.000000
I20260812 06:17:54.330732 30021 maintenance_manager.cc:643] P 859dcf640ba347adaa34ad374fecbf18: MajorDeltaCompactionOp(0fd0f4143f2343169fc3d394632a64cd) complete. Timing: real 0.180s	user 0.146s	sys 0.034s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":33020621,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1033,"lbm_read_time_us":14186,"lbm_reads_lt_1ms":773,"lbm_write_time_us":35988,"lbm_writes_lt_1ms":743,"mutex_wait_us":28,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":15360,"update_count":3500}
I20260812 06:17:54.331305 30132 maintenance_manager.cc:419] P 859dcf640ba347adaa34ad374fecbf18: Scheduling FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd): perf score=14.095187
I20260812 06:17:54.369649 30021 maintenance_manager.cc:643] P 859dcf640ba347adaa34ad374fecbf18: FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd) complete. Timing: real 0.038s	user 0.023s	sys 0.011s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":16516,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:54.370563 30132 maintenance_manager.cc:419] P 859dcf640ba347adaa34ad374fecbf18: Scheduling FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd): perf score=2.188937
I20260812 06:17:54.383177 30021 maintenance_manager.cc:643] P 859dcf640ba347adaa34ad374fecbf18: FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd) complete. Timing: real 0.012s	user 0.006s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4765,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:54.383631 30132 maintenance_manager.cc:419] P 859dcf640ba347adaa34ad374fecbf18: Scheduling MajorDeltaCompactionOp(0fd0f4143f2343169fc3d394632a64cd): perf score=1.000000
I20260812 06:17:54.543310 30021 maintenance_manager.cc:643] P 859dcf640ba347adaa34ad374fecbf18: MajorDeltaCompactionOp(0fd0f4143f2343169fc3d394632a64cd) complete. Timing: real 0.160s	user 0.101s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1637,"lbm_read_time_us":10282,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29456,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1536,"update_count":2500}
I20260812 06:17:54.543828 30132 maintenance_manager.cc:419] P 859dcf640ba347adaa34ad374fecbf18: Scheduling FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd): perf score=14.095187
I20260812 06:17:54.602794 30021 maintenance_manager.cc:643] P 859dcf640ba347adaa34ad374fecbf18: FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd) complete. Timing: real 0.059s	user 0.028s	sys 0.016s Metrics: {"bytes_written":16409899,"delete_count":0,"lbm_write_time_us":20137,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:54.603349 30132 maintenance_manager.cc:419] P 859dcf640ba347adaa34ad374fecbf18: Scheduling FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd): perf score=2.188937
I20260812 06:17:54.613296 30021 maintenance_manager.cc:643] P 859dcf640ba347adaa34ad374fecbf18: FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3702,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:54.613915 30132 maintenance_manager.cc:419] P 859dcf640ba347adaa34ad374fecbf18: Scheduling MajorDeltaCompactionOp(0fd0f4143f2343169fc3d394632a64cd): perf score=1.000000
I20260812 06:17:54.777489 30021 maintenance_manager.cc:643] P 859dcf640ba347adaa34ad374fecbf18: MajorDeltaCompactionOp(0fd0f4143f2343169fc3d394632a64cd) complete. Timing: real 0.163s	user 0.087s	sys 0.074s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815681,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":127,"lbm_read_time_us":12977,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25836,"lbm_writes_lt_1ms":543,"mutex_wait_us":28,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":26112,"update_count":2500}
I20260812 06:17:54.778203 30132 maintenance_manager.cc:419] P 859dcf640ba347adaa34ad374fecbf18: Scheduling FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd): perf score=14.095187
I20260812 06:17:54.833734 30021 maintenance_manager.cc:643] P 859dcf640ba347adaa34ad374fecbf18: FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd) complete. Timing: real 0.055s	user 0.030s	sys 0.017s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21859,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:54.834317 30132 maintenance_manager.cc:419] P 859dcf640ba347adaa34ad374fecbf18: Scheduling FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd): perf score=2.188937
I20260812 06:17:54.850217 30021 maintenance_manager.cc:643] P 859dcf640ba347adaa34ad374fecbf18: FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd) complete. Timing: real 0.016s	user 0.015s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6137,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:54.850747 30132 maintenance_manager.cc:419] P 859dcf640ba347adaa34ad374fecbf18: Scheduling MajorDeltaCompactionOp(0fd0f4143f2343169fc3d394632a64cd): perf score=1.000000
I20260812 06:17:55.006871 30021 maintenance_manager.cc:643] P 859dcf640ba347adaa34ad374fecbf18: MajorDeltaCompactionOp(0fd0f4143f2343169fc3d394632a64cd) complete. Timing: real 0.156s	user 0.092s	sys 0.064s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":278,"lbm_read_time_us":10839,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27549,"lbm_writes_lt_1ms":543,"mutex_wait_us":53,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1536,"update_count":2500}
I20260812 06:17:55.007505 30132 maintenance_manager.cc:419] P 859dcf640ba347adaa34ad374fecbf18: Scheduling FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd): perf score=14.095187
I20260812 06:17:55.058620 30021 maintenance_manager.cc:643] P 859dcf640ba347adaa34ad374fecbf18: FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd) complete. Timing: real 0.051s	user 0.023s	sys 0.027s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18429,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":24576,"update_count":2000}
I20260812 06:17:55.059150 30132 maintenance_manager.cc:419] P 859dcf640ba347adaa34ad374fecbf18: Scheduling FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd): perf score=2.188937
I20260812 06:17:55.068846 30021 maintenance_manager.cc:643] P 859dcf640ba347adaa34ad374fecbf18: FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3775,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:55.069327 30132 maintenance_manager.cc:419] P 859dcf640ba347adaa34ad374fecbf18: Scheduling FlushMRSOp(0fd0f4143f2343169fc3d394632a64cd): perf score=1.000000
I20260812 06:17:55.108227 30021 maintenance_manager.cc:643] P 859dcf640ba347adaa34ad374fecbf18: FlushMRSOp(0fd0f4143f2343169fc3d394632a64cd) complete. Timing: real 0.039s	user 0.014s	sys 0.011s Metrics: {"bytes_written":1193507,"cfile_init":1,"dirs.queue_time_us":51,"dirs.run_cpu_time_us":195,"dirs.run_wall_time_us":884,"drs_written":1,"lbm_read_time_us":36,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1468,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:55.108889 30132 maintenance_manager.cc:419] P 859dcf640ba347adaa34ad374fecbf18: Scheduling LogGCOp(0fd0f4143f2343169fc3d394632a64cd): free 108535638 bytes of WAL
I20260812 06:17:55.109120 30021 log_reader.cc:385] T 0fd0f4143f2343169fc3d394632a64cd: removed 11 log segments from log reader
I20260812 06:17:55.109180 30021 log.cc:1079] T 0fd0f4143f2343169fc3d394632a64cd P 859dcf640ba347adaa34ad374fecbf18: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/0fd0f4143f2343169fc3d394632a64cd/wal-000000029 (ops 137-141)
I20260812 06:17:55.109216 30021 log.cc:1079] T 0fd0f4143f2343169fc3d394632a64cd P 859dcf640ba347adaa34ad374fecbf18: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/0fd0f4143f2343169fc3d394632a64cd/wal-000000030 (ops 142-146)
I20260812 06:17:55.109248 30021 log.cc:1079] T 0fd0f4143f2343169fc3d394632a64cd P 859dcf640ba347adaa34ad374fecbf18: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/0fd0f4143f2343169fc3d394632a64cd/wal-000000031 (ops 147-150)
I20260812 06:17:55.109282 30021 log.cc:1079] T 0fd0f4143f2343169fc3d394632a64cd P 859dcf640ba347adaa34ad374fecbf18: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/0fd0f4143f2343169fc3d394632a64cd/wal-000000032 (ops 151-155)
I20260812 06:17:55.109310 30021 log.cc:1079] T 0fd0f4143f2343169fc3d394632a64cd P 859dcf640ba347adaa34ad374fecbf18: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/0fd0f4143f2343169fc3d394632a64cd/wal-000000033 (ops 156-160)
I20260812 06:17:55.109338 30021 log.cc:1079] T 0fd0f4143f2343169fc3d394632a64cd P 859dcf640ba347adaa34ad374fecbf18: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/0fd0f4143f2343169fc3d394632a64cd/wal-000000034 (ops 161-164)
I20260812 06:17:55.109365 30021 log.cc:1079] T 0fd0f4143f2343169fc3d394632a64cd P 859dcf640ba347adaa34ad374fecbf18: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/0fd0f4143f2343169fc3d394632a64cd/wal-000000035 (ops 165-169)
I20260812 06:17:55.109395 30021 log.cc:1079] T 0fd0f4143f2343169fc3d394632a64cd P 859dcf640ba347adaa34ad374fecbf18: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/0fd0f4143f2343169fc3d394632a64cd/wal-000000036 (ops 170-174)
I20260812 06:17:55.109427 30021 log.cc:1079] T 0fd0f4143f2343169fc3d394632a64cd P 859dcf640ba347adaa34ad374fecbf18: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/0fd0f4143f2343169fc3d394632a64cd/wal-000000037 (ops 175-179)
I20260812 06:17:55.109455 30021 log.cc:1079] T 0fd0f4143f2343169fc3d394632a64cd P 859dcf640ba347adaa34ad374fecbf18: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/0fd0f4143f2343169fc3d394632a64cd/wal-000000038 (ops 180-184)
I20260812 06:17:55.109483 30021 log.cc:1079] T 0fd0f4143f2343169fc3d394632a64cd P 859dcf640ba347adaa34ad374fecbf18: Deleting log segment in path: /tmp/dist-test-taskAbAEcX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465523567-29460-0/minicluster-data/ts-0-root/wals/0fd0f4143f2343169fc3d394632a64cd/wal-000000039 (ops 185-189)
I20260812 06:17:55.133623 30021 maintenance_manager.cc:643] P 859dcf640ba347adaa34ad374fecbf18: LogGCOp(0fd0f4143f2343169fc3d394632a64cd) complete. Timing: real 0.025s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:17:55.134132 30132 maintenance_manager.cc:419] P 859dcf640ba347adaa34ad374fecbf18: Scheduling FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd): perf score=3.181125
I20260812 06:17:55.154800 30021 maintenance_manager.cc:643] P 859dcf640ba347adaa34ad374fecbf18: FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd) complete. Timing: real 0.020s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4813,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:55.155246 30132 maintenance_manager.cc:419] P 859dcf640ba347adaa34ad374fecbf18: Scheduling UndoDeltaBlockGCOp(0fd0f4143f2343169fc3d394632a64cd): 462 bytes on disk
I20260812 06:17:55.155691 30021 maintenance_manager.cc:643] P 859dcf640ba347adaa34ad374fecbf18: UndoDeltaBlockGCOp(0fd0f4143f2343169fc3d394632a64cd) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4}
I20260812 06:17:55.156209 30132 maintenance_manager.cc:419] P 859dcf640ba347adaa34ad374fecbf18: Scheduling FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd): perf score=2.188937
I20260812 06:17:55.169777 30021 maintenance_manager.cc:643] P 859dcf640ba347adaa34ad374fecbf18: FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd) complete. Timing: real 0.013s	user 0.008s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4935,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:55.170323 30132 maintenance_manager.cc:419] P 859dcf640ba347adaa34ad374fecbf18: Scheduling MajorDeltaCompactionOp(0fd0f4143f2343169fc3d394632a64cd): perf score=1.000000
I20260812 06:17:55.291927 29460 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.556s	user 1.656s	sys 0.160s
I20260812 06:17:55.375263 30021 maintenance_manager.cc:643] P 859dcf640ba347adaa34ad374fecbf18: MajorDeltaCompactionOp(0fd0f4143f2343169fc3d394632a64cd) complete. Timing: real 0.205s	user 0.129s	sys 0.076s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020735,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":231,"lbm_read_time_us":13817,"lbm_reads_lt_1ms":770,"lbm_write_time_us":34997,"lbm_writes_lt_1ms":743,"mutex_wait_us":55,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":206464,"thread_start_us":69,"threads_started":1,"update_count":3500}
I20260812 06:17:55.375923 30132 maintenance_manager.cc:419] P 859dcf640ba347adaa34ad374fecbf18: Scheduling FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd): perf score=10.126437
I20260812 06:17:55.384184 29460 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.092s	user 0.001s	sys 0.000s
I20260812 06:17:55.384641 29460 tablet_server.cc:179] TabletServer@127.28.197.1:0 shutting down...
I20260812 06:17:55.405789 30021 maintenance_manager.cc:643] P 859dcf640ba347adaa34ad374fecbf18: FlushDeltaMemStoresOp(0fd0f4143f2343169fc3d394632a64cd) complete. Timing: real 0.030s	user 0.009s	sys 0.017s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13217,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:55.406314 29460 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:55.406518 29460 tablet_replica.cc:333] T 0fd0f4143f2343169fc3d394632a64cd P 859dcf640ba347adaa34ad374fecbf18: stopping tablet replica
I20260812 06:17:55.406646 29460 raft_consensus.cc:2243] T 0fd0f4143f2343169fc3d394632a64cd P 859dcf640ba347adaa34ad374fecbf18 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:55.406839 29460 raft_consensus.cc:2272] T 0fd0f4143f2343169fc3d394632a64cd P 859dcf640ba347adaa34ad374fecbf18 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:55.410264 29460 tablet_server.cc:196] TabletServer@127.28.197.1:0 shutdown complete.
I20260812 06:17:55.432152 29460 master.cc:562] Master@127.28.197.62:35081 shutting down...
I20260812 06:17:55.435007 29460 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 3c9fab2d7ea14600a12df726dd10a2de [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:55.435158 29460 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 3c9fab2d7ea14600a12df726dd10a2de [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:55.435223 29460 tablet_replica.cc:333] T 00000000000000000000000000000000 P 3c9fab2d7ea14600a12df726dd10a2de: stopping tablet replica
I20260812 06:17:55.447098 29460 master.cc:584] Master@127.28.197.62:35081 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (4962 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (9989 ms total)

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