[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:19:36.320312 18470 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.18.9.190:46571
I20260812 06:19:36.321370 18470 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:19:36.322014 18470 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:36.328292 18477 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:19:36.328342 18476 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:36.328536 18470 server_base.cc:1061] running on GCE node
W20260812 06:19:36.328627 18479 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:36.329171 18470 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:36.329268 18470 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:36.329347 18470 hybrid_clock.cc:648] HybridClock initialized: now 1786515576329344 us; error 0 us; skew 500 ppm
I20260812 06:19:36.331218 18470 webserver.cc:533] Webserver started at http://127.18.9.190:33703/ using document root <none> and password file <none>
I20260812 06:19:36.331811 18470 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:36.331898 18470 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:36.332165 18470 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:36.333868 18470 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576309717-18470-0/minicluster-data/master-0-root/instance:
uuid: "ac2c22add3234fac89f05f5b77514b7c"
format_stamp: "Formatted at 2026-08-12 06:19:36 on dist-test-slave-69rg"
I20260812 06:19:36.337374 18470 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.002s	sys 0.001s
I20260812 06:19:36.339505 18489 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:36.340530 18470 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:19:36.340667 18470 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576309717-18470-0/minicluster-data/master-0-root
uuid: "ac2c22add3234fac89f05f5b77514b7c"
format_stamp: "Formatted at 2026-08-12 06:19:36 on dist-test-slave-69rg"
I20260812 06:19:36.340790 18470 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576309717-18470-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576309717-18470-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576309717-18470-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:36.355084 18470 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:36.355695 18470 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:19:36.355883 18470 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:36.363855 18470 rpc_server.cc:307] RPC server started. Bound to: 127.18.9.190:46571
I20260812 06:19:36.363860 18548 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.18.9.190:46571 every 8 connection(s)
I20260812 06:19:36.366200 18549 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:36.371619 18549 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P ac2c22add3234fac89f05f5b77514b7c: Bootstrap starting.
I20260812 06:19:36.374135 18549 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P ac2c22add3234fac89f05f5b77514b7c: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:36.375042 18549 log.cc:826] T 00000000000000000000000000000000 P ac2c22add3234fac89f05f5b77514b7c: Log is configured to *not* fsync() on all Append() calls
I20260812 06:19:36.376786 18549 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P ac2c22add3234fac89f05f5b77514b7c: No bootstrap required, opened a new log
I20260812 06:19:36.379586 18549 raft_consensus.cc:359] T 00000000000000000000000000000000 P ac2c22add3234fac89f05f5b77514b7c [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ac2c22add3234fac89f05f5b77514b7c" member_type: VOTER }
I20260812 06:19:36.379746 18549 raft_consensus.cc:385] T 00000000000000000000000000000000 P ac2c22add3234fac89f05f5b77514b7c [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:36.379846 18549 raft_consensus.cc:740] T 00000000000000000000000000000000 P ac2c22add3234fac89f05f5b77514b7c [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: ac2c22add3234fac89f05f5b77514b7c, State: Initialized, Role: FOLLOWER
I20260812 06:19:36.380429 18549 consensus_queue.cc:260] T 00000000000000000000000000000000 P ac2c22add3234fac89f05f5b77514b7c [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: "ac2c22add3234fac89f05f5b77514b7c" member_type: VOTER }
I20260812 06:19:36.380589 18549 raft_consensus.cc:399] T 00000000000000000000000000000000 P ac2c22add3234fac89f05f5b77514b7c [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:36.380668 18549 raft_consensus.cc:493] T 00000000000000000000000000000000 P ac2c22add3234fac89f05f5b77514b7c [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:36.380836 18549 raft_consensus.cc:3060] T 00000000000000000000000000000000 P ac2c22add3234fac89f05f5b77514b7c [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:36.381601 18549 raft_consensus.cc:515] T 00000000000000000000000000000000 P ac2c22add3234fac89f05f5b77514b7c [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ac2c22add3234fac89f05f5b77514b7c" member_type: VOTER }
I20260812 06:19:36.382087 18549 leader_election.cc:304] T 00000000000000000000000000000000 P ac2c22add3234fac89f05f5b77514b7c [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: ac2c22add3234fac89f05f5b77514b7c; no voters: 
I20260812 06:19:36.382417 18549 leader_election.cc:290] T 00000000000000000000000000000000 P ac2c22add3234fac89f05f5b77514b7c [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:36.382593 18553 raft_consensus.cc:2804] T 00000000000000000000000000000000 P ac2c22add3234fac89f05f5b77514b7c [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:36.382853 18553 raft_consensus.cc:697] T 00000000000000000000000000000000 P ac2c22add3234fac89f05f5b77514b7c [term 1 LEADER]: Becoming Leader. State: Replica: ac2c22add3234fac89f05f5b77514b7c, State: Running, Role: LEADER
I20260812 06:19:36.383327 18553 consensus_queue.cc:237] T 00000000000000000000000000000000 P ac2c22add3234fac89f05f5b77514b7c [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: "ac2c22add3234fac89f05f5b77514b7c" member_type: VOTER }
I20260812 06:19:36.383373 18549 sys_catalog.cc:565] T 00000000000000000000000000000000 P ac2c22add3234fac89f05f5b77514b7c [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:36.385283 18554 sys_catalog.cc:455] T 00000000000000000000000000000000 P ac2c22add3234fac89f05f5b77514b7c [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "ac2c22add3234fac89f05f5b77514b7c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ac2c22add3234fac89f05f5b77514b7c" member_type: VOTER } }
I20260812 06:19:36.385303 18555 sys_catalog.cc:455] T 00000000000000000000000000000000 P ac2c22add3234fac89f05f5b77514b7c [sys.catalog]: SysCatalogTable state changed. Reason: New leader ac2c22add3234fac89f05f5b77514b7c. Latest consensus state: current_term: 1 leader_uuid: "ac2c22add3234fac89f05f5b77514b7c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ac2c22add3234fac89f05f5b77514b7c" member_type: VOTER } }
I20260812 06:19:36.385419 18554 sys_catalog.cc:458] T 00000000000000000000000000000000 P ac2c22add3234fac89f05f5b77514b7c [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:36.385491 18555 sys_catalog.cc:458] T 00000000000000000000000000000000 P ac2c22add3234fac89f05f5b77514b7c [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:36.385972 18570 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:36.386122 18470 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:36.388064 18570 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:36.392553 18570 catalog_manager.cc:1383] Generated new cluster ID: 2c05ae06a71c437e9b9687597f7222b3
I20260812 06:19:36.392619 18570 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:36.400596 18570 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:36.401537 18570 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:36.410168 18570 catalog_manager.cc:6092] T 00000000000000000000000000000000 P ac2c22add3234fac89f05f5b77514b7c: Generated new TSK 0
I20260812 06:19:36.410864 18570 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:36.419018 18470 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:36.422004 18577 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:36.422117 18470 server_base.cc:1061] running on GCE node
W20260812 06:19:36.422006 18576 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:36.422047 18579 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:36.422483 18470 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:36.422528 18470 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:36.422542 18470 hybrid_clock.cc:648] HybridClock initialized: now 1786515576422543 us; error 0 us; skew 500 ppm
I20260812 06:19:36.423480 18470 webserver.cc:533] Webserver started at http://127.18.9.129:38023/ using document root <none> and password file <none>
I20260812 06:19:36.423669 18470 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:36.423722 18470 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:36.423822 18470 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:36.424220 18470 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576309717-18470-0/minicluster-data/ts-0-root/instance:
uuid: "e367e66b1e7c4990b1925fe38bc7354d"
format_stamp: "Formatted at 2026-08-12 06:19:36 on dist-test-slave-69rg"
I20260812 06:19:36.425715 18470 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:36.426750 18586 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:36.426996 18470 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:36.427067 18470 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576309717-18470-0/minicluster-data/ts-0-root
uuid: "e367e66b1e7c4990b1925fe38bc7354d"
format_stamp: "Formatted at 2026-08-12 06:19:36 on dist-test-slave-69rg"
I20260812 06:19:36.427155 18470 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576309717-18470-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576309717-18470-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576309717-18470-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:36.446205 18470 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:36.446658 18470 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:36.447180 18470 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:36.448006 18470 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:36.448058 18470 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:36.448137 18470 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:36.448180 18470 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:36.455495 18470 rpc_server.cc:307] RPC server started. Bound to: 127.18.9.129:45943
I20260812 06:19:36.455530 18669 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.18.9.129:45943 every 8 connection(s)
I20260812 06:19:36.465314 18670 heartbeater.cc:344] Connected to a master server at 127.18.9.190:46571
I20260812 06:19:36.465555 18670 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:36.466065 18670 heartbeater.cc:507] Master 127.18.9.190:46571 requested a full tablet report, sending...
I20260812 06:19:36.467530 18508 ts_manager.cc:194] Registered new tserver with Master: e367e66b1e7c4990b1925fe38bc7354d (127.18.9.129:45943)
I20260812 06:19:36.467651 18470 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011481752s
I20260812 06:19:36.469046 18508 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:39074
I20260812 06:19:36.478094 18508 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:39082:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:36.491844 18619 tablet_service.cc:1511] Processing CreateTablet for tablet c17fd43d1c74493c85ea78b100971416 (DEFAULT_TABLE table=heavy-update-compaction-test [id=00ff58d898b2454aa20cae70f8d28bc8]), partition=
I20260812 06:19:36.492398 18619 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet c17fd43d1c74493c85ea78b100971416. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:36.494637 18684 tablet_bootstrap.cc:492] T c17fd43d1c74493c85ea78b100971416 P e367e66b1e7c4990b1925fe38bc7354d: Bootstrap starting.
I20260812 06:19:36.495673 18684 tablet_bootstrap.cc:654] T c17fd43d1c74493c85ea78b100971416 P e367e66b1e7c4990b1925fe38bc7354d: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:36.496865 18684 tablet_bootstrap.cc:492] T c17fd43d1c74493c85ea78b100971416 P e367e66b1e7c4990b1925fe38bc7354d: No bootstrap required, opened a new log
I20260812 06:19:36.496968 18684 ts_tablet_manager.cc:1403] T c17fd43d1c74493c85ea78b100971416 P e367e66b1e7c4990b1925fe38bc7354d: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:36.497422 18684 raft_consensus.cc:359] T c17fd43d1c74493c85ea78b100971416 P e367e66b1e7c4990b1925fe38bc7354d [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e367e66b1e7c4990b1925fe38bc7354d" member_type: VOTER last_known_addr { host: "127.18.9.129" port: 45943 } }
I20260812 06:19:36.497537 18684 raft_consensus.cc:385] T c17fd43d1c74493c85ea78b100971416 P e367e66b1e7c4990b1925fe38bc7354d [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:36.497570 18684 raft_consensus.cc:740] T c17fd43d1c74493c85ea78b100971416 P e367e66b1e7c4990b1925fe38bc7354d [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: e367e66b1e7c4990b1925fe38bc7354d, State: Initialized, Role: FOLLOWER
I20260812 06:19:36.497691 18684 consensus_queue.cc:260] T c17fd43d1c74493c85ea78b100971416 P e367e66b1e7c4990b1925fe38bc7354d [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: "e367e66b1e7c4990b1925fe38bc7354d" member_type: VOTER last_known_addr { host: "127.18.9.129" port: 45943 } }
I20260812 06:19:36.497778 18684 raft_consensus.cc:399] T c17fd43d1c74493c85ea78b100971416 P e367e66b1e7c4990b1925fe38bc7354d [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:36.497845 18684 raft_consensus.cc:493] T c17fd43d1c74493c85ea78b100971416 P e367e66b1e7c4990b1925fe38bc7354d [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:36.497897 18684 raft_consensus.cc:3060] T c17fd43d1c74493c85ea78b100971416 P e367e66b1e7c4990b1925fe38bc7354d [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:36.498818 18684 raft_consensus.cc:515] T c17fd43d1c74493c85ea78b100971416 P e367e66b1e7c4990b1925fe38bc7354d [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e367e66b1e7c4990b1925fe38bc7354d" member_type: VOTER last_known_addr { host: "127.18.9.129" port: 45943 } }
I20260812 06:19:36.498955 18684 leader_election.cc:304] T c17fd43d1c74493c85ea78b100971416 P e367e66b1e7c4990b1925fe38bc7354d [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: e367e66b1e7c4990b1925fe38bc7354d; no voters: 
I20260812 06:19:36.499135 18684 leader_election.cc:290] T c17fd43d1c74493c85ea78b100971416 P e367e66b1e7c4990b1925fe38bc7354d [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:36.499423 18684 ts_tablet_manager.cc:1434] T c17fd43d1c74493c85ea78b100971416 P e367e66b1e7c4990b1925fe38bc7354d: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:19:36.499496 18688 raft_consensus.cc:2804] T c17fd43d1c74493c85ea78b100971416 P e367e66b1e7c4990b1925fe38bc7354d [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:36.499923 18670 heartbeater.cc:499] Master 127.18.9.190:46571 was elected leader, sending a full tablet report...
I20260812 06:19:36.500101 18688 raft_consensus.cc:697] T c17fd43d1c74493c85ea78b100971416 P e367e66b1e7c4990b1925fe38bc7354d [term 1 LEADER]: Becoming Leader. State: Replica: e367e66b1e7c4990b1925fe38bc7354d, State: Running, Role: LEADER
I20260812 06:19:36.500226 18688 consensus_queue.cc:237] T c17fd43d1c74493c85ea78b100971416 P e367e66b1e7c4990b1925fe38bc7354d [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: "e367e66b1e7c4990b1925fe38bc7354d" member_type: VOTER last_known_addr { host: "127.18.9.129" port: 45943 } }
I20260812 06:19:36.502786 18508 catalog_manager.cc:5719] T c17fd43d1c74493c85ea78b100971416 P e367e66b1e7c4990b1925fe38bc7354d reported cstate change: term changed from 0 to 1, leader changed from <none> to e367e66b1e7c4990b1925fe38bc7354d (127.18.9.129). New cstate: current_term: 1 leader_uuid: "e367e66b1e7c4990b1925fe38bc7354d" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e367e66b1e7c4990b1925fe38bc7354d" member_type: VOTER last_known_addr { host: "127.18.9.129" port: 45943 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:36.573789 18470 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.061s	user 0.014s	sys 0.015s
I20260812 06:19:36.706583 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling FlushMRSOp(c17fd43d1c74493c85ea78b100971416): perf score=19.054940
I20260812 06:19:36.884416 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: FlushMRSOp(c17fd43d1c74493c85ea78b100971416) complete. Timing: real 0.177s	user 0.130s	sys 0.032s Metrics: {"bytes_written":12307490,"cfile_init":1,"compiler_manager_pool.queue_time_us":207,"delete_count":0,"dirs.queue_time_us":83,"dirs.run_cpu_time_us":228,"dirs.run_wall_time_us":975,"drs_written":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4,"lbm_write_time_us":43320,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":116,"threads_started":1,"update_count":1500}
I20260812 06:19:36.885634 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling LogGCOp(c17fd43d1c74493c85ea78b100971416): free 20743880 bytes of WAL
I20260812 06:19:36.886019 18591 log_reader.cc:385] T c17fd43d1c74493c85ea78b100971416: removed 2 log segments from log reader
I20260812 06:19:36.886109 18591 log.cc:1079] T c17fd43d1c74493c85ea78b100971416 P e367e66b1e7c4990b1925fe38bc7354d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/c17fd43d1c74493c85ea78b100971416/wal-000000001 (ops 1-6)
I20260812 06:19:36.886173 18591 log.cc:1079] T c17fd43d1c74493c85ea78b100971416 P e367e66b1e7c4990b1925fe38bc7354d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/c17fd43d1c74493c85ea78b100971416/wal-000000002 (ops 7-11)
I20260812 06:19:36.891891 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: LogGCOp(c17fd43d1c74493c85ea78b100971416) complete. Timing: real 0.006s	user 0.001s	sys 0.003s Metrics: {}
I20260812 06:19:36.892365 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling UndoDeltaBlockGCOp(c17fd43d1c74493c85ea78b100971416): 16411392 bytes on disk
I20260812 06:19:36.893127 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: UndoDeltaBlockGCOp(c17fd43d1c74493c85ea78b100971416) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":83,"lbm_reads_lt_1ms":4}
I20260812 06:19:36.893690 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416): perf score=2.188937
I20260812 06:19:36.930409 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416) complete. Timing: real 0.037s	user 0.009s	sys 0.013s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6005,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:36.931015 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416): perf score=2.188937
I20260812 06:19:36.943070 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416) complete. Timing: real 0.012s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4810,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:36.943502 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling MajorDeltaCompactionOp(c17fd43d1c74493c85ea78b100971416): perf score=1.000000
I20260812 06:19:37.114919 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: MajorDeltaCompactionOp(c17fd43d1c74493c85ea78b100971416) complete. Timing: real 0.171s	user 0.128s	sys 0.043s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774808,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":914,"lbm_read_time_us":11944,"lbm_reads_lt_1ms":569,"lbm_write_time_us":29286,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"thread_start_us":310,"threads_started":5,"update_count":2500}
I20260812 06:19:37.115463 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416): perf score=10.126437
I20260812 06:19:37.165164 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416) complete. Timing: real 0.050s	user 0.025s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17963,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:37.165675 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416): perf score=2.188937
I20260812 06:19:37.178496 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416) complete. Timing: real 0.013s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4600,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:37.179060 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling MajorDeltaCompactionOp(c17fd43d1c74493c85ea78b100971416): perf score=1.000000
I20260812 06:19:37.307659 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: MajorDeltaCompactionOp(c17fd43d1c74493c85ea78b100971416) complete. Timing: real 0.128s	user 0.090s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":691,"lbm_read_time_us":9371,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24316,"lbm_writes_lt_1ms":443,"mutex_wait_us":315,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14080,"update_count":2000}
I20260812 06:19:37.308336 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416): perf score=10.126437
I20260812 06:19:37.351904 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416) complete. Timing: real 0.043s	user 0.022s	sys 0.016s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":17342,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:37.352406 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416): perf score=2.188937
I20260812 06:19:37.363763 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4308,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:37.364365 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling MajorDeltaCompactionOp(c17fd43d1c74493c85ea78b100971416): perf score=1.000000
I20260812 06:19:37.498243 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: MajorDeltaCompactionOp(c17fd43d1c74493c85ea78b100971416) complete. Timing: real 0.134s	user 0.114s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":221,"lbm_read_time_us":9660,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26446,"lbm_writes_lt_1ms":443,"mutex_wait_us":30,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":18432,"update_count":2000}
I20260812 06:19:37.498839 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416): perf score=10.126437
I20260812 06:19:37.543835 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416) complete. Timing: real 0.045s	user 0.023s	sys 0.012s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":16062,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:37.544360 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416): perf score=2.188937
I20260812 06:19:37.555363 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4266,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:37.556070 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling MajorDeltaCompactionOp(c17fd43d1c74493c85ea78b100971416): perf score=1.000000
I20260812 06:19:37.680214 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: MajorDeltaCompactionOp(c17fd43d1c74493c85ea78b100971416) complete. Timing: real 0.124s	user 0.108s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":375,"lbm_read_time_us":9036,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23453,"lbm_writes_lt_1ms":443,"mutex_wait_us":46,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":20736,"update_count":2000}
I20260812 06:19:37.680918 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416): perf score=10.126437
I20260812 06:19:37.733667 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416) complete. Timing: real 0.053s	user 0.027s	sys 0.020s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":20810,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:19:37.734243 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416): perf score=2.188937
I20260812 06:19:37.745129 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4300,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:37.745561 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling MajorDeltaCompactionOp(c17fd43d1c74493c85ea78b100971416): perf score=1.000000
I20260812 06:19:37.894327 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: MajorDeltaCompactionOp(c17fd43d1c74493c85ea78b100971416) complete. Timing: real 0.149s	user 0.105s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":862,"lbm_read_time_us":10481,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25174,"lbm_writes_lt_1ms":443,"mutex_wait_us":181,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4224,"update_count":2000}
I20260812 06:19:37.894856 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416): perf score=10.126437
I20260812 06:19:37.940299 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416) complete. Timing: real 0.045s	user 0.025s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15460,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:37.940776 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416): perf score=2.188937
I20260812 06:19:37.952176 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4359,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:37.952863 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling MajorDeltaCompactionOp(c17fd43d1c74493c85ea78b100971416): perf score=1.000000
I20260812 06:19:38.079941 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: MajorDeltaCompactionOp(c17fd43d1c74493c85ea78b100971416) complete. Timing: real 0.127s	user 0.095s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":193,"lbm_read_time_us":7534,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26693,"lbm_writes_lt_1ms":443,"mutex_wait_us":46,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2000}
I20260812 06:19:38.080561 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416): perf score=10.126437
I20260812 06:19:38.121943 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416) complete. Timing: real 0.041s	user 0.022s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14268,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:38.122511 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416): perf score=2.188937
I20260812 06:19:38.138839 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416) complete. Timing: real 0.016s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6131,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:38.139518 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling FlushMRSOp(c17fd43d1c74493c85ea78b100971416): perf score=1.000000
I20260812 06:19:38.167487 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: FlushMRSOp(c17fd43d1c74493c85ea78b100971416) complete. Timing: real 0.027s	user 0.026s	sys 0.000s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":64,"dirs.run_cpu_time_us":224,"dirs.run_wall_time_us":1489,"drs_written":1,"lbm_read_time_us":36,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1590,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:19:38.168318 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling LogGCOp(c17fd43d1c74493c85ea78b100971416): free 112239257 bytes of WAL
I20260812 06:19:38.168620 18591 log_reader.cc:385] T c17fd43d1c74493c85ea78b100971416: removed 11 log segments from log reader
I20260812 06:19:38.168691 18591 log.cc:1079] T c17fd43d1c74493c85ea78b100971416 P e367e66b1e7c4990b1925fe38bc7354d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/c17fd43d1c74493c85ea78b100971416/wal-000000003 (ops 12-16)
I20260812 06:19:38.168730 18591 log.cc:1079] T c17fd43d1c74493c85ea78b100971416 P e367e66b1e7c4990b1925fe38bc7354d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/c17fd43d1c74493c85ea78b100971416/wal-000000004 (ops 17-20)
I20260812 06:19:38.168762 18591 log.cc:1079] T c17fd43d1c74493c85ea78b100971416 P e367e66b1e7c4990b1925fe38bc7354d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/c17fd43d1c74493c85ea78b100971416/wal-000000005 (ops 21-25)
I20260812 06:19:38.168790 18591 log.cc:1079] T c17fd43d1c74493c85ea78b100971416 P e367e66b1e7c4990b1925fe38bc7354d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/c17fd43d1c74493c85ea78b100971416/wal-000000006 (ops 26-30)
I20260812 06:19:38.168833 18591 log.cc:1079] T c17fd43d1c74493c85ea78b100971416 P e367e66b1e7c4990b1925fe38bc7354d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/c17fd43d1c74493c85ea78b100971416/wal-000000007 (ops 31-35)
I20260812 06:19:38.168857 18591 log.cc:1079] T c17fd43d1c74493c85ea78b100971416 P e367e66b1e7c4990b1925fe38bc7354d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/c17fd43d1c74493c85ea78b100971416/wal-000000008 (ops 36-40)
I20260812 06:19:38.168886 18591 log.cc:1079] T c17fd43d1c74493c85ea78b100971416 P e367e66b1e7c4990b1925fe38bc7354d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/c17fd43d1c74493c85ea78b100971416/wal-000000009 (ops 41-45)
I20260812 06:19:38.168915 18591 log.cc:1079] T c17fd43d1c74493c85ea78b100971416 P e367e66b1e7c4990b1925fe38bc7354d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/c17fd43d1c74493c85ea78b100971416/wal-000000010 (ops 46-50)
I20260812 06:19:38.168947 18591 log.cc:1079] T c17fd43d1c74493c85ea78b100971416 P e367e66b1e7c4990b1925fe38bc7354d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/c17fd43d1c74493c85ea78b100971416/wal-000000011 (ops 51-55)
I20260812 06:19:38.168982 18591 log.cc:1079] T c17fd43d1c74493c85ea78b100971416 P e367e66b1e7c4990b1925fe38bc7354d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/c17fd43d1c74493c85ea78b100971416/wal-000000012 (ops 56-60)
I20260812 06:19:38.169013 18591 log.cc:1079] T c17fd43d1c74493c85ea78b100971416 P e367e66b1e7c4990b1925fe38bc7354d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/c17fd43d1c74493c85ea78b100971416/wal-000000013 (ops 61-65)
I20260812 06:19:38.197610 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: LogGCOp(c17fd43d1c74493c85ea78b100971416) complete. Timing: real 0.029s	user 0.002s	sys 0.023s Metrics: {}
I20260812 06:19:38.198132 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416): perf score=2.188937
I20260812 06:19:38.220142 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416) complete. Timing: real 0.022s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6016,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":500}
I20260812 06:19:38.220607 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416): perf score=2.188937
I20260812 06:19:38.231647 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4222,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:38.232123 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling UndoDeltaBlockGCOp(c17fd43d1c74493c85ea78b100971416): 461 bytes on disk
I20260812 06:19:38.232750 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: UndoDeltaBlockGCOp(c17fd43d1c74493c85ea78b100971416) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":121,"lbm_reads_lt_1ms":4}
I20260812 06:19:38.233487 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling MajorDeltaCompactionOp(c17fd43d1c74493c85ea78b100971416): perf score=1.000000
I20260812 06:19:38.406010 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: MajorDeltaCompactionOp(c17fd43d1c74493c85ea78b100971416) complete. Timing: real 0.172s	user 0.138s	sys 0.032s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877339,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":509,"lbm_read_time_us":11011,"lbm_reads_lt_1ms":674,"lbm_write_time_us":36513,"lbm_writes_lt_1ms":643,"mutex_wait_us":40,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3840,"thread_start_us":97,"threads_started":1,"update_count":3000}
I20260812 06:19:38.406663 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416): perf score=14.095187
I20260812 06:19:38.458424 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416) complete. Timing: real 0.052s	user 0.029s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20159,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:38.458978 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416): perf score=2.188937
I20260812 06:19:38.474541 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416) complete. Timing: real 0.015s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5896,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:38.475191 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling MajorDeltaCompactionOp(c17fd43d1c74493c85ea78b100971416): perf score=1.000000
I20260812 06:19:38.635494 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: MajorDeltaCompactionOp(c17fd43d1c74493c85ea78b100971416) complete. Timing: real 0.160s	user 0.109s	sys 0.038s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":318,"lbm_read_time_us":9315,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30027,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":25344,"update_count":2500}
I20260812 06:19:38.636209 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416): perf score=14.095187
I20260812 06:19:38.710589 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416) complete. Timing: real 0.074s	user 0.039s	sys 0.020s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":26669,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:38.711090 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416): perf score=2.188937
I20260812 06:19:38.722409 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3975,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:38.722955 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling MajorDeltaCompactionOp(c17fd43d1c74493c85ea78b100971416): perf score=1.000000
I20260812 06:19:38.901405 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: MajorDeltaCompactionOp(c17fd43d1c74493c85ea78b100971416) complete. Timing: real 0.178s	user 0.124s	sys 0.045s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":365,"lbm_read_time_us":11313,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31412,"lbm_writes_lt_1ms":543,"mutex_wait_us":60,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":105600,"update_count":2500}
I20260812 06:19:38.902043 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416): perf score=14.095187
I20260812 06:19:38.954833 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416) complete. Timing: real 0.053s	user 0.040s	sys 0.008s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22019,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:38.955417 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416): perf score=2.188937
I20260812 06:19:38.967976 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4635,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:38.968461 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling MajorDeltaCompactionOp(c17fd43d1c74493c85ea78b100971416): perf score=1.000000
I20260812 06:19:39.149290 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: MajorDeltaCompactionOp(c17fd43d1c74493c85ea78b100971416) complete. Timing: real 0.181s	user 0.132s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":694,"lbm_read_time_us":13838,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29995,"lbm_writes_lt_1ms":543,"mutex_wait_us":297,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7040,"update_count":2500}
I20260812 06:19:39.150038 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416): perf score=14.095187
I20260812 06:19:39.212239 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416) complete. Timing: real 0.062s	user 0.036s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22311,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:39.212806 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416): perf score=2.188937
I20260812 06:19:39.224049 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4534,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:39.224548 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling MajorDeltaCompactionOp(c17fd43d1c74493c85ea78b100971416): perf score=1.000000
I20260812 06:19:39.415217 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: MajorDeltaCompactionOp(c17fd43d1c74493c85ea78b100971416) complete. Timing: real 0.190s	user 0.134s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":195,"lbm_read_time_us":13115,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31187,"lbm_writes_lt_1ms":543,"mutex_wait_us":3,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2500}
I20260812 06:19:39.415964 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416): perf score=14.095187
I20260812 06:19:39.479717 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416) complete. Timing: real 0.064s	user 0.030s	sys 0.023s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21243,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:39.480232 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416): perf score=2.188937
I20260812 06:19:39.490934 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4177,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:39.491434 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling MajorDeltaCompactionOp(c17fd43d1c74493c85ea78b100971416): perf score=1.000000
I20260812 06:19:39.677188 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: MajorDeltaCompactionOp(c17fd43d1c74493c85ea78b100971416) complete. Timing: real 0.186s	user 0.147s	sys 0.032s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":514,"lbm_read_time_us":13914,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29435,"lbm_writes_lt_1ms":543,"mutex_wait_us":339,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12032,"update_count":2500}
I20260812 06:19:39.677994 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416): perf score=11.118625
I20260812 06:19:39.720881 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416) complete. Timing: real 0.043s	user 0.018s	sys 0.022s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":18331,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:39.721516 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416): perf score=2.188937
I20260812 06:19:39.736431 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416) complete. Timing: real 0.015s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4959,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:39.736999 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling FlushMRSOp(c17fd43d1c74493c85ea78b100971416): perf score=1.000000
I20260812 06:19:39.796352 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: FlushMRSOp(c17fd43d1c74493c85ea78b100971416) complete. Timing: real 0.059s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":90,"dirs.run_cpu_time_us":239,"dirs.run_wall_time_us":1326,"drs_written":1,"lbm_read_time_us":75,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1924,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:19:39.797173 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling LogGCOp(c17fd43d1c74493c85ea78b100971416): free 129320556 bytes of WAL
I20260812 06:19:39.797446 18591 log_reader.cc:385] T c17fd43d1c74493c85ea78b100971416: removed 13 log segments from log reader
I20260812 06:19:39.797508 18591 log.cc:1079] T c17fd43d1c74493c85ea78b100971416 P e367e66b1e7c4990b1925fe38bc7354d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/c17fd43d1c74493c85ea78b100971416/wal-000000014 (ops 66-70)
I20260812 06:19:39.797549 18591 log.cc:1079] T c17fd43d1c74493c85ea78b100971416 P e367e66b1e7c4990b1925fe38bc7354d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/c17fd43d1c74493c85ea78b100971416/wal-000000015 (ops 71-75)
I20260812 06:19:39.797578 18591 log.cc:1079] T c17fd43d1c74493c85ea78b100971416 P e367e66b1e7c4990b1925fe38bc7354d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/c17fd43d1c74493c85ea78b100971416/wal-000000016 (ops 76-80)
I20260812 06:19:39.797606 18591 log.cc:1079] T c17fd43d1c74493c85ea78b100971416 P e367e66b1e7c4990b1925fe38bc7354d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/c17fd43d1c74493c85ea78b100971416/wal-000000017 (ops 81-84)
I20260812 06:19:39.797636 18591 log.cc:1079] T c17fd43d1c74493c85ea78b100971416 P e367e66b1e7c4990b1925fe38bc7354d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/c17fd43d1c74493c85ea78b100971416/wal-000000018 (ops 85-89)
I20260812 06:19:39.797680 18591 log.cc:1079] T c17fd43d1c74493c85ea78b100971416 P e367e66b1e7c4990b1925fe38bc7354d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/c17fd43d1c74493c85ea78b100971416/wal-000000019 (ops 90-94)
I20260812 06:19:39.797709 18591 log.cc:1079] T c17fd43d1c74493c85ea78b100971416 P e367e66b1e7c4990b1925fe38bc7354d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/c17fd43d1c74493c85ea78b100971416/wal-000000020 (ops 95-99)
I20260812 06:19:39.797739 18591 log.cc:1079] T c17fd43d1c74493c85ea78b100971416 P e367e66b1e7c4990b1925fe38bc7354d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/c17fd43d1c74493c85ea78b100971416/wal-000000021 (ops 100-104)
I20260812 06:19:39.797765 18591 log.cc:1079] T c17fd43d1c74493c85ea78b100971416 P e367e66b1e7c4990b1925fe38bc7354d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/c17fd43d1c74493c85ea78b100971416/wal-000000022 (ops 105-109)
I20260812 06:19:39.797794 18591 log.cc:1079] T c17fd43d1c74493c85ea78b100971416 P e367e66b1e7c4990b1925fe38bc7354d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/c17fd43d1c74493c85ea78b100971416/wal-000000023 (ops 110-114)
I20260812 06:19:39.797870 18591 log.cc:1079] T c17fd43d1c74493c85ea78b100971416 P e367e66b1e7c4990b1925fe38bc7354d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/c17fd43d1c74493c85ea78b100971416/wal-000000024 (ops 115-118)
I20260812 06:19:39.797899 18591 log.cc:1079] T c17fd43d1c74493c85ea78b100971416 P e367e66b1e7c4990b1925fe38bc7354d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/c17fd43d1c74493c85ea78b100971416/wal-000000025 (ops 119-123)
I20260812 06:19:39.797922 18591 log.cc:1079] T c17fd43d1c74493c85ea78b100971416 P e367e66b1e7c4990b1925fe38bc7354d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/c17fd43d1c74493c85ea78b100971416/wal-000000026 (ops 124-128)
I20260812 06:19:39.831023 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: LogGCOp(c17fd43d1c74493c85ea78b100971416) complete. Timing: real 0.034s	user 0.001s	sys 0.031s Metrics: {}
I20260812 06:19:39.831485 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416): perf score=7.149875
I20260812 06:19:39.862951 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416) complete. Timing: real 0.031s	user 0.021s	sys 0.004s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":10924,"lbm_writes_lt_1ms":213,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":1050}
I20260812 06:19:39.863420 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling LogGCOp(c17fd43d1c74493c85ea78b100971416): free 12017947 bytes of WAL
I20260812 06:19:39.863667 18591 log_reader.cc:385] T c17fd43d1c74493c85ea78b100971416: removed 1 log segments from log reader
I20260812 06:19:39.863731 18591 log.cc:1079] T c17fd43d1c74493c85ea78b100971416 P e367e66b1e7c4990b1925fe38bc7354d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/c17fd43d1c74493c85ea78b100971416/wal-000000027 (ops 129-133)
I20260812 06:19:39.866756 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: LogGCOp(c17fd43d1c74493c85ea78b100971416) complete. Timing: real 0.003s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:19:39.867065 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416): perf score=2.188937
I20260812 06:19:39.876864 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3886,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:39.877254 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling MajorDeltaCompactionOp(c17fd43d1c74493c85ea78b100971416): perf score=1.000000
I20260812 06:19:40.104390 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: MajorDeltaCompactionOp(c17fd43d1c74493c85ea78b100971416) complete. Timing: real 0.227s	user 0.148s	sys 0.075s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979735,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":918,"lbm_read_time_us":15384,"lbm_reads_lt_1ms":774,"lbm_write_time_us":40670,"lbm_writes_lt_1ms":743,"mutex_wait_us":357,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":82,"threads_started":1,"update_count":3500}
I20260812 06:19:40.105223 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416): perf score=16.079562
I20260812 06:19:40.155860 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416) complete. Timing: real 0.050s	user 0.023s	sys 0.024s Metrics: {"bytes_written":17722675,"delete_count":0,"lbm_write_time_us":22003,"lbm_writes_lt_1ms":435,"reinsert_count":0,"update_count":2160}
I20260812 06:19:40.156347 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416): perf score=2.188937
I20260812 06:19:40.169039 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416) complete. Timing: real 0.013s	user 0.000s	sys 0.008s Metrics: {"bytes_written":3200109,"delete_count":0,"lbm_write_time_us":3538,"lbm_writes_lt_1ms":81,"reinsert_count":0,"update_count":390}
I20260812 06:19:40.169500 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling UndoDeltaBlockGCOp(c17fd43d1c74493c85ea78b100971416): 493 bytes on disk
I20260812 06:19:40.169945 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: UndoDeltaBlockGCOp(c17fd43d1c74493c85ea78b100971416) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4}
I20260812 06:19:40.170428 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416): perf score=2.188937
I20260812 06:19:40.179849 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3552,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:40.180263 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling MajorDeltaCompactionOp(c17fd43d1c74493c85ea78b100971416): perf score=1.000000
I20260812 06:19:40.385943 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: MajorDeltaCompactionOp(c17fd43d1c74493c85ea78b100971416) complete. Timing: real 0.205s	user 0.150s	sys 0.054s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877189,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":530,"lbm_read_time_us":15905,"lbm_reads_lt_1ms":673,"lbm_write_time_us":33430,"lbm_writes_lt_1ms":643,"mutex_wait_us":285,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":14080,"update_count":3000}
I20260812 06:19:40.386672 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416): perf score=14.095187
I20260812 06:19:40.445863 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416) complete. Timing: real 0.059s	user 0.040s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":25257,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:40.446535 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416): perf score=3.181125
I20260812 06:19:40.464051 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416) complete. Timing: real 0.017s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":7157,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:40.464619 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416): perf score=2.188937
I20260812 06:19:40.474159 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416) complete. Timing: real 0.009s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3636,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:40.474727 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling MajorDeltaCompactionOp(c17fd43d1c74493c85ea78b100971416): perf score=1.000000
I20260812 06:19:40.682763 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: MajorDeltaCompactionOp(c17fd43d1c74493c85ea78b100971416) complete. Timing: real 0.208s	user 0.133s	sys 0.075s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877207,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":497,"lbm_read_time_us":15544,"lbm_reads_lt_1ms":673,"lbm_write_time_us":35039,"lbm_writes_lt_1ms":643,"mutex_wait_us":136,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":3000}
I20260812 06:19:40.683516 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416): perf score=14.095187
I20260812 06:19:40.745215 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416) complete. Timing: real 0.061s	user 0.030s	sys 0.020s Metrics: {"bytes_written":16409908,"delete_count":0,"lbm_write_time_us":23827,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:40.745728 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416): perf score=2.188937
I20260812 06:19:40.756305 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4162,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:40.756814 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling MajorDeltaCompactionOp(c17fd43d1c74493c85ea78b100971416): perf score=1.000000
I20260812 06:19:40.939373 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: MajorDeltaCompactionOp(c17fd43d1c74493c85ea78b100971416) complete. Timing: real 0.182s	user 0.123s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774695,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":376,"lbm_read_time_us":11925,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30038,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6016,"update_count":2500}
I20260812 06:19:40.940074 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416): perf score=14.095187
I20260812 06:19:41.001217 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416) complete. Timing: real 0.061s	user 0.029s	sys 0.025s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21579,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:41.001921 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416): perf score=2.188937
I20260812 06:19:41.012598 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4184,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:41.013062 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling MajorDeltaCompactionOp(c17fd43d1c74493c85ea78b100971416): perf score=1.000000
I20260812 06:19:41.188102 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: MajorDeltaCompactionOp(c17fd43d1c74493c85ea78b100971416) complete. Timing: real 0.175s	user 0.129s	sys 0.043s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":197,"lbm_read_time_us":12291,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29266,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8960,"update_count":2500}
I20260812 06:19:41.188874 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416): perf score=14.095187
I20260812 06:19:41.250481 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416) complete. Timing: real 0.061s	user 0.043s	sys 0.015s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22522,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:41.251049 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416): perf score=2.188937
I20260812 06:19:41.261734 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4282,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:41.262221 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling FlushMRSOp(c17fd43d1c74493c85ea78b100971416): perf score=1.000000
I20260812 06:19:41.302857 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: FlushMRSOp(c17fd43d1c74493c85ea78b100971416) complete. Timing: real 0.040s	user 0.027s	sys 0.005s Metrics: {"bytes_written":1193507,"cfile_init":1,"dirs.queue_time_us":71,"dirs.run_cpu_time_us":298,"dirs.run_wall_time_us":1310,"drs_written":1,"lbm_read_time_us":65,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1918,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:19:41.303596 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling LogGCOp(c17fd43d1c74493c85ea78b100971416): free 112239509 bytes of WAL
I20260812 06:19:41.303838 18591 log_reader.cc:385] T c17fd43d1c74493c85ea78b100971416: removed 11 log segments from log reader
I20260812 06:19:41.303884 18591 log.cc:1079] T c17fd43d1c74493c85ea78b100971416 P e367e66b1e7c4990b1925fe38bc7354d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/c17fd43d1c74493c85ea78b100971416/wal-000000028 (ops 134-138)
I20260812 06:19:41.303913 18591 log.cc:1079] T c17fd43d1c74493c85ea78b100971416 P e367e66b1e7c4990b1925fe38bc7354d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/c17fd43d1c74493c85ea78b100971416/wal-000000029 (ops 139-143)
I20260812 06:19:41.303979 18591 log.cc:1079] T c17fd43d1c74493c85ea78b100971416 P e367e66b1e7c4990b1925fe38bc7354d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/c17fd43d1c74493c85ea78b100971416/wal-000000030 (ops 144-148)
I20260812 06:19:41.304023 18591 log.cc:1079] T c17fd43d1c74493c85ea78b100971416 P e367e66b1e7c4990b1925fe38bc7354d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/c17fd43d1c74493c85ea78b100971416/wal-000000031 (ops 149-152)
I20260812 06:19:41.304064 18591 log.cc:1079] T c17fd43d1c74493c85ea78b100971416 P e367e66b1e7c4990b1925fe38bc7354d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/c17fd43d1c74493c85ea78b100971416/wal-000000032 (ops 153-157)
I20260812 06:19:41.304126 18591 log.cc:1079] T c17fd43d1c74493c85ea78b100971416 P e367e66b1e7c4990b1925fe38bc7354d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/c17fd43d1c74493c85ea78b100971416/wal-000000033 (ops 158-162)
I20260812 06:19:41.304162 18591 log.cc:1079] T c17fd43d1c74493c85ea78b100971416 P e367e66b1e7c4990b1925fe38bc7354d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/c17fd43d1c74493c85ea78b100971416/wal-000000034 (ops 163-167)
I20260812 06:19:41.304207 18591 log.cc:1079] T c17fd43d1c74493c85ea78b100971416 P e367e66b1e7c4990b1925fe38bc7354d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/c17fd43d1c74493c85ea78b100971416/wal-000000035 (ops 168-172)
I20260812 06:19:41.304252 18591 log.cc:1079] T c17fd43d1c74493c85ea78b100971416 P e367e66b1e7c4990b1925fe38bc7354d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/c17fd43d1c74493c85ea78b100971416/wal-000000036 (ops 173-177)
I20260812 06:19:41.304292 18591 log.cc:1079] T c17fd43d1c74493c85ea78b100971416 P e367e66b1e7c4990b1925fe38bc7354d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/c17fd43d1c74493c85ea78b100971416/wal-000000037 (ops 178-182)
I20260812 06:19:41.304332 18591 log.cc:1079] T c17fd43d1c74493c85ea78b100971416 P e367e66b1e7c4990b1925fe38bc7354d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/c17fd43d1c74493c85ea78b100971416/wal-000000038 (ops 183-187)
I20260812 06:19:41.329192 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: LogGCOp(c17fd43d1c74493c85ea78b100971416) complete. Timing: real 0.025s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:19:41.329592 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling UndoDeltaBlockGCOp(c17fd43d1c74493c85ea78b100971416): 462 bytes on disk
I20260812 06:19:41.330082 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: UndoDeltaBlockGCOp(c17fd43d1c74493c85ea78b100971416) 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:19:41.330672 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416): perf score=2.188937
I20260812 06:19:41.353637 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416) complete. Timing: real 0.023s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6176,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:41.354163 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416): perf score=2.188937
I20260812 06:19:41.364140 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3907,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:41.364562 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling MajorDeltaCompactionOp(c17fd43d1c74493c85ea78b100971416): perf score=1.000000
I20260812 06:19:41.552518 18470 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.979s	user 1.822s	sys 0.199s
I20260812 06:19:41.581749 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: MajorDeltaCompactionOp(c17fd43d1c74493c85ea78b100971416) complete. Timing: real 0.217s	user 0.150s	sys 0.063s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979750,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":15727,"lbm_reads_lt_1ms":770,"lbm_write_time_us":38227,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":3840,"update_count":3500}
I20260812 06:19:41.582333 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416): perf score=14.095187
I20260812 06:19:41.616168 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: FlushDeltaMemStoresOp(c17fd43d1c74493c85ea78b100971416) complete. Timing: real 0.034s	user 0.020s	sys 0.012s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":16536,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:41.616669 18671 maintenance_manager.cc:419] P e367e66b1e7c4990b1925fe38bc7354d: Scheduling MajorDeltaCompactionOp(c17fd43d1c74493c85ea78b100971416): perf score=1.000000
I20260812 06:19:41.662974 18470 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.110s	user 0.002s	sys 0.000s
I20260812 06:19:41.663631 18470 tablet_server.cc:179] TabletServer@127.18.9.129:0 shutting down...
I20260812 06:19:41.745438 18591 maintenance_manager.cc:643] P e367e66b1e7c4990b1925fe38bc7354d: MajorDeltaCompactionOp(c17fd43d1c74493c85ea78b100971416) complete. Timing: real 0.129s	user 0.096s	sys 0.032s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672158,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1052,"lbm_read_time_us":9217,"lbm_reads_lt_1ms":467,"lbm_write_time_us":28093,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":441,"mutex_wait_us":323,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6400,"update_count":2000}
I20260812 06:19:41.746124 18470 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:41.746511 18470 tablet_replica.cc:333] T c17fd43d1c74493c85ea78b100971416 P e367e66b1e7c4990b1925fe38bc7354d: stopping tablet replica
I20260812 06:19:41.746781 18470 raft_consensus.cc:2243] T c17fd43d1c74493c85ea78b100971416 P e367e66b1e7c4990b1925fe38bc7354d [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:41.747044 18470 raft_consensus.cc:2272] T c17fd43d1c74493c85ea78b100971416 P e367e66b1e7c4990b1925fe38bc7354d [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:41.752099 18470 tablet_server.cc:196] TabletServer@127.18.9.129:0 shutdown complete.
I20260812 06:19:41.784978 18470 master.cc:562] Master@127.18.9.190:46571 shutting down...
I20260812 06:19:41.788916 18470 raft_consensus.cc:2243] T 00000000000000000000000000000000 P ac2c22add3234fac89f05f5b77514b7c [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:41.789111 18470 raft_consensus.cc:2272] T 00000000000000000000000000000000 P ac2c22add3234fac89f05f5b77514b7c [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:41.789197 18470 tablet_replica.cc:333] T 00000000000000000000000000000000 P ac2c22add3234fac89f05f5b77514b7c: stopping tablet replica
I20260812 06:19:41.801690 18470 master.cc:584] Master@127.18.9.190:46571 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5572 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:19:41.892338 18470 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.18.9.190:41639
I20260812 06:19:41.892681 18470 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:41.894769 18711 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:41.894840 18707 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:41.894944 18708 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:41.894958 18470 server_base.cc:1061] running on GCE node
I20260812 06:19:41.895304 18470 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:41.895376 18470 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:41.895401 18470 hybrid_clock.cc:648] HybridClock initialized: now 1786515581895400 us; error 0 us; skew 500 ppm
I20260812 06:19:41.896253 18470 webserver.cc:533] Webserver started at http://127.18.9.190:33511/ using document root <none> and password file <none>
I20260812 06:19:41.896425 18470 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:41.896492 18470 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:41.896570 18470 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:41.896958 18470 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576309717-18470-0/minicluster-data/master-0-root/instance:
uuid: "11cec9012b1a4cb48fa8ab563d2fd0f1"
format_stamp: "Formatted at 2026-08-12 06:19:41 on dist-test-slave-69rg"
I20260812 06:19:41.898626 18470 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:41.899573 18716 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:41.899833 18470 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:41.899926 18470 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576309717-18470-0/minicluster-data/master-0-root
uuid: "11cec9012b1a4cb48fa8ab563d2fd0f1"
format_stamp: "Formatted at 2026-08-12 06:19:41 on dist-test-slave-69rg"
I20260812 06:19:41.900017 18470 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576309717-18470-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576309717-18470-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576309717-18470-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:41.908751 18470 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:41.909147 18470 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:41.914110 18470 rpc_server.cc:307] RPC server started. Bound to: 127.18.9.190:41639
I20260812 06:19:41.918220 18778 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:41.918330 18777 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.18.9.190:41639 every 8 connection(s)
I20260812 06:19:41.932170 18778 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 11cec9012b1a4cb48fa8ab563d2fd0f1: Bootstrap starting.
I20260812 06:19:41.933084 18778 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 11cec9012b1a4cb48fa8ab563d2fd0f1: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:41.934260 18778 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 11cec9012b1a4cb48fa8ab563d2fd0f1: No bootstrap required, opened a new log
I20260812 06:19:41.934702 18778 raft_consensus.cc:359] T 00000000000000000000000000000000 P 11cec9012b1a4cb48fa8ab563d2fd0f1 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "11cec9012b1a4cb48fa8ab563d2fd0f1" member_type: VOTER }
I20260812 06:19:41.934793 18778 raft_consensus.cc:385] T 00000000000000000000000000000000 P 11cec9012b1a4cb48fa8ab563d2fd0f1 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:41.934818 18778 raft_consensus.cc:740] T 00000000000000000000000000000000 P 11cec9012b1a4cb48fa8ab563d2fd0f1 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 11cec9012b1a4cb48fa8ab563d2fd0f1, State: Initialized, Role: FOLLOWER
I20260812 06:19:41.935011 18778 consensus_queue.cc:260] T 00000000000000000000000000000000 P 11cec9012b1a4cb48fa8ab563d2fd0f1 [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: "11cec9012b1a4cb48fa8ab563d2fd0f1" member_type: VOTER }
I20260812 06:19:41.935088 18778 raft_consensus.cc:399] T 00000000000000000000000000000000 P 11cec9012b1a4cb48fa8ab563d2fd0f1 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:41.935150 18778 raft_consensus.cc:493] T 00000000000000000000000000000000 P 11cec9012b1a4cb48fa8ab563d2fd0f1 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:41.935212 18778 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 11cec9012b1a4cb48fa8ab563d2fd0f1 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:41.935966 18778 raft_consensus.cc:515] T 00000000000000000000000000000000 P 11cec9012b1a4cb48fa8ab563d2fd0f1 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "11cec9012b1a4cb48fa8ab563d2fd0f1" member_type: VOTER }
I20260812 06:19:41.936127 18778 leader_election.cc:304] T 00000000000000000000000000000000 P 11cec9012b1a4cb48fa8ab563d2fd0f1 [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: 11cec9012b1a4cb48fa8ab563d2fd0f1; no voters: 
I20260812 06:19:41.936354 18778 leader_election.cc:290] T 00000000000000000000000000000000 P 11cec9012b1a4cb48fa8ab563d2fd0f1 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:41.936484 18783 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 11cec9012b1a4cb48fa8ab563d2fd0f1 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:41.936761 18783 raft_consensus.cc:697] T 00000000000000000000000000000000 P 11cec9012b1a4cb48fa8ab563d2fd0f1 [term 1 LEADER]: Becoming Leader. State: Replica: 11cec9012b1a4cb48fa8ab563d2fd0f1, State: Running, Role: LEADER
I20260812 06:19:41.936864 18778 sys_catalog.cc:565] T 00000000000000000000000000000000 P 11cec9012b1a4cb48fa8ab563d2fd0f1 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:41.936910 18783 consensus_queue.cc:237] T 00000000000000000000000000000000 P 11cec9012b1a4cb48fa8ab563d2fd0f1 [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: "11cec9012b1a4cb48fa8ab563d2fd0f1" member_type: VOTER }
I20260812 06:19:41.937358 18786 sys_catalog.cc:455] T 00000000000000000000000000000000 P 11cec9012b1a4cb48fa8ab563d2fd0f1 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 11cec9012b1a4cb48fa8ab563d2fd0f1. Latest consensus state: current_term: 1 leader_uuid: "11cec9012b1a4cb48fa8ab563d2fd0f1" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "11cec9012b1a4cb48fa8ab563d2fd0f1" member_type: VOTER } }
I20260812 06:19:41.937345 18784 sys_catalog.cc:455] T 00000000000000000000000000000000 P 11cec9012b1a4cb48fa8ab563d2fd0f1 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "11cec9012b1a4cb48fa8ab563d2fd0f1" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "11cec9012b1a4cb48fa8ab563d2fd0f1" member_type: VOTER } }
I20260812 06:19:41.937489 18786 sys_catalog.cc:458] T 00000000000000000000000000000000 P 11cec9012b1a4cb48fa8ab563d2fd0f1 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:41.937597 18784 sys_catalog.cc:458] T 00000000000000000000000000000000 P 11cec9012b1a4cb48fa8ab563d2fd0f1 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:41.938163 18790 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:41.938822 18790 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:41.938994 18470 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:41.940681 18790 catalog_manager.cc:1383] Generated new cluster ID: aca4d4d52f7b4ad5937f8522c5d0343a
I20260812 06:19:41.940740 18790 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:41.950371 18790 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:41.950914 18790 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:41.957662 18790 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 11cec9012b1a4cb48fa8ab563d2fd0f1: Generated new TSK 0
I20260812 06:19:41.957870 18790 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:41.971467 18470 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:41.973256 18808 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:41.973256 18809 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:19:41.973433 18812 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:41.973713 18470 server_base.cc:1061] running on GCE node
I20260812 06:19:41.973912 18470 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:41.973970 18470 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:41.974005 18470 hybrid_clock.cc:648] HybridClock initialized: now 1786515581974004 us; error 0 us; skew 500 ppm
I20260812 06:19:41.974929 18470 webserver.cc:533] Webserver started at http://127.18.9.129:44491/ using document root <none> and password file <none>
I20260812 06:19:41.975107 18470 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:41.975181 18470 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:41.975296 18470 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:41.975703 18470 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576309717-18470-0/minicluster-data/ts-0-root/instance:
uuid: "17f2ee1f59f84a25a5d1b4577041106d"
format_stamp: "Formatted at 2026-08-12 06:19:41 on dist-test-slave-69rg"
I20260812 06:19:41.977262 18470 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:41.978297 18818 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:41.978583 18470 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.000s
I20260812 06:19:41.978673 18470 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576309717-18470-0/minicluster-data/ts-0-root
uuid: "17f2ee1f59f84a25a5d1b4577041106d"
format_stamp: "Formatted at 2026-08-12 06:19:41 on dist-test-slave-69rg"
I20260812 06:19:41.978763 18470 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576309717-18470-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576309717-18470-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576309717-18470-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:41.990731 18470 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:41.991114 18470 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:41.991453 18470 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:41.992168 18470 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:41.992241 18470 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:41.992295 18470 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:41.992347 18470 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:41.996899 18470 rpc_server.cc:307] RPC server started. Bound to: 127.18.9.129:36845
I20260812 06:19:41.996937 18889 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.18.9.129:36845 every 8 connection(s)
I20260812 06:19:42.006289 18890 heartbeater.cc:344] Connected to a master server at 127.18.9.190:41639
I20260812 06:19:42.006417 18890 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:42.006650 18890 heartbeater.cc:507] Master 127.18.9.190:41639 requested a full tablet report, sending...
I20260812 06:19:42.007311 18737 ts_manager.cc:194] Registered new tserver with Master: 17f2ee1f59f84a25a5d1b4577041106d (127.18.9.129:36845)
I20260812 06:19:42.007395 18470 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.010075991s
I20260812 06:19:42.008174 18737 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:60908
I20260812 06:19:42.014849 18737 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:60920:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:42.023438 18852 tablet_service.cc:1511] Processing CreateTablet for tablet fe576f8bfde24159aa5d81d8db983e34 (DEFAULT_TABLE table=heavy-update-compaction-test [id=c1d80a2594b24a32ac3ff716c9175026]), partition=
I20260812 06:19:42.023684 18852 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet fe576f8bfde24159aa5d81d8db983e34. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:42.025480 18903 tablet_bootstrap.cc:492] T fe576f8bfde24159aa5d81d8db983e34 P 17f2ee1f59f84a25a5d1b4577041106d: Bootstrap starting.
I20260812 06:19:42.026463 18903 tablet_bootstrap.cc:654] T fe576f8bfde24159aa5d81d8db983e34 P 17f2ee1f59f84a25a5d1b4577041106d: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:42.027802 18903 tablet_bootstrap.cc:492] T fe576f8bfde24159aa5d81d8db983e34 P 17f2ee1f59f84a25a5d1b4577041106d: No bootstrap required, opened a new log
I20260812 06:19:42.027904 18903 ts_tablet_manager.cc:1403] T fe576f8bfde24159aa5d81d8db983e34 P 17f2ee1f59f84a25a5d1b4577041106d: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:42.028470 18903 raft_consensus.cc:359] T fe576f8bfde24159aa5d81d8db983e34 P 17f2ee1f59f84a25a5d1b4577041106d [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "17f2ee1f59f84a25a5d1b4577041106d" member_type: VOTER last_known_addr { host: "127.18.9.129" port: 36845 } }
I20260812 06:19:42.028587 18903 raft_consensus.cc:385] T fe576f8bfde24159aa5d81d8db983e34 P 17f2ee1f59f84a25a5d1b4577041106d [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:42.028623 18903 raft_consensus.cc:740] T fe576f8bfde24159aa5d81d8db983e34 P 17f2ee1f59f84a25a5d1b4577041106d [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 17f2ee1f59f84a25a5d1b4577041106d, State: Initialized, Role: FOLLOWER
I20260812 06:19:42.028767 18903 consensus_queue.cc:260] T fe576f8bfde24159aa5d81d8db983e34 P 17f2ee1f59f84a25a5d1b4577041106d [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: "17f2ee1f59f84a25a5d1b4577041106d" member_type: VOTER last_known_addr { host: "127.18.9.129" port: 36845 } }
I20260812 06:19:42.028867 18903 raft_consensus.cc:399] T fe576f8bfde24159aa5d81d8db983e34 P 17f2ee1f59f84a25a5d1b4577041106d [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:42.028919 18903 raft_consensus.cc:493] T fe576f8bfde24159aa5d81d8db983e34 P 17f2ee1f59f84a25a5d1b4577041106d [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:42.028980 18903 raft_consensus.cc:3060] T fe576f8bfde24159aa5d81d8db983e34 P 17f2ee1f59f84a25a5d1b4577041106d [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:42.029682 18903 raft_consensus.cc:515] T fe576f8bfde24159aa5d81d8db983e34 P 17f2ee1f59f84a25a5d1b4577041106d [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "17f2ee1f59f84a25a5d1b4577041106d" member_type: VOTER last_known_addr { host: "127.18.9.129" port: 36845 } }
I20260812 06:19:42.029801 18903 leader_election.cc:304] T fe576f8bfde24159aa5d81d8db983e34 P 17f2ee1f59f84a25a5d1b4577041106d [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: 17f2ee1f59f84a25a5d1b4577041106d; no voters: 
I20260812 06:19:42.030035 18903 leader_election.cc:290] T fe576f8bfde24159aa5d81d8db983e34 P 17f2ee1f59f84a25a5d1b4577041106d [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:42.030192 18905 raft_consensus.cc:2804] T fe576f8bfde24159aa5d81d8db983e34 P 17f2ee1f59f84a25a5d1b4577041106d [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:42.030362 18905 raft_consensus.cc:697] T fe576f8bfde24159aa5d81d8db983e34 P 17f2ee1f59f84a25a5d1b4577041106d [term 1 LEADER]: Becoming Leader. State: Replica: 17f2ee1f59f84a25a5d1b4577041106d, State: Running, Role: LEADER
I20260812 06:19:42.030375 18903 ts_tablet_manager.cc:1434] T fe576f8bfde24159aa5d81d8db983e34 P 17f2ee1f59f84a25a5d1b4577041106d: Time spent starting tablet: real 0.002s	user 0.001s	sys 0.002s
I20260812 06:19:42.030411 18890 heartbeater.cc:499] Master 127.18.9.190:41639 was elected leader, sending a full tablet report...
I20260812 06:19:42.030532 18905 consensus_queue.cc:237] T fe576f8bfde24159aa5d81d8db983e34 P 17f2ee1f59f84a25a5d1b4577041106d [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: "17f2ee1f59f84a25a5d1b4577041106d" member_type: VOTER last_known_addr { host: "127.18.9.129" port: 36845 } }
I20260812 06:19:42.031821 18737 catalog_manager.cc:5719] T fe576f8bfde24159aa5d81d8db983e34 P 17f2ee1f59f84a25a5d1b4577041106d reported cstate change: term changed from 0 to 1, leader changed from <none> to 17f2ee1f59f84a25a5d1b4577041106d (127.18.9.129). New cstate: current_term: 1 leader_uuid: "17f2ee1f59f84a25a5d1b4577041106d" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "17f2ee1f59f84a25a5d1b4577041106d" member_type: VOTER last_known_addr { host: "127.18.9.129" port: 36845 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:42.094349 18470 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.055s	user 0.018s	sys 0.007s
I20260812 06:19:42.247862 18892 maintenance_manager.cc:419] P 17f2ee1f59f84a25a5d1b4577041106d: Scheduling FlushMRSOp(fe576f8bfde24159aa5d81d8db983e34): perf score=19.054940
I20260812 06:19:42.404273 18825 maintenance_manager.cc:643] P 17f2ee1f59f84a25a5d1b4577041106d: FlushMRSOp(fe576f8bfde24159aa5d81d8db983e34) complete. Timing: real 0.156s	user 0.093s	sys 0.061s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":95,"dirs.run_cpu_time_us":279,"dirs.run_wall_time_us":843,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":41191,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:19:42.404914 18892 maintenance_manager.cc:419] P 17f2ee1f59f84a25a5d1b4577041106d: Scheduling LogGCOp(fe576f8bfde24159aa5d81d8db983e34): free 20743880 bytes of WAL
I20260812 06:19:42.405187 18825 log_reader.cc:385] T fe576f8bfde24159aa5d81d8db983e34: removed 2 log segments from log reader
I20260812 06:19:42.405300 18825 log.cc:1079] T fe576f8bfde24159aa5d81d8db983e34 P 17f2ee1f59f84a25a5d1b4577041106d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/fe576f8bfde24159aa5d81d8db983e34/wal-000000001 (ops 1-6)
I20260812 06:19:42.405395 18825 log.cc:1079] T fe576f8bfde24159aa5d81d8db983e34 P 17f2ee1f59f84a25a5d1b4577041106d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/fe576f8bfde24159aa5d81d8db983e34/wal-000000002 (ops 7-11)
I20260812 06:19:42.410521 18825 maintenance_manager.cc:643] P 17f2ee1f59f84a25a5d1b4577041106d: LogGCOp(fe576f8bfde24159aa5d81d8db983e34) complete. Timing: real 0.005s	user 0.000s	sys 0.005s Metrics: {}
I20260812 06:19:42.410846 18892 maintenance_manager.cc:419] P 17f2ee1f59f84a25a5d1b4577041106d: Scheduling UndoDeltaBlockGCOp(fe576f8bfde24159aa5d81d8db983e34): 16411396 bytes on disk
I20260812 06:19:42.411257 18825 maintenance_manager.cc:643] P 17f2ee1f59f84a25a5d1b4577041106d: UndoDeltaBlockGCOp(fe576f8bfde24159aa5d81d8db983e34) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4}
I20260812 06:19:42.411643 18892 maintenance_manager.cc:419] P 17f2ee1f59f84a25a5d1b4577041106d: Scheduling FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34): perf score=2.188937
I20260812 06:19:42.435119 18825 maintenance_manager.cc:643] P 17f2ee1f59f84a25a5d1b4577041106d: FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34) complete. Timing: real 0.023s	user 0.004s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4438,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:42.435551 18892 maintenance_manager.cc:419] P 17f2ee1f59f84a25a5d1b4577041106d: Scheduling FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34): perf score=2.188937
I20260812 06:19:42.456135 18825 maintenance_manager.cc:643] P 17f2ee1f59f84a25a5d1b4577041106d: FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34) complete. Timing: real 0.020s	user 0.012s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4319,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:42.456655 18892 maintenance_manager.cc:419] P 17f2ee1f59f84a25a5d1b4577041106d: Scheduling MajorDeltaCompactionOp(fe576f8bfde24159aa5d81d8db983e34): perf score=1.000000
I20260812 06:19:42.652657 18825 maintenance_manager.cc:643] P 17f2ee1f59f84a25a5d1b4577041106d: MajorDeltaCompactionOp(fe576f8bfde24159aa5d81d8db983e34) complete. Timing: real 0.196s	user 0.106s	sys 0.084s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774808,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":548,"lbm_read_time_us":12930,"lbm_reads_lt_1ms":569,"lbm_write_time_us":33125,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":384,"thread_start_us":316,"threads_started":5,"update_count":2500}
I20260812 06:19:42.653206 18892 maintenance_manager.cc:419] P 17f2ee1f59f84a25a5d1b4577041106d: Scheduling FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34): perf score=14.095187
I20260812 06:19:42.714448 18825 maintenance_manager.cc:643] P 17f2ee1f59f84a25a5d1b4577041106d: FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34) complete. Timing: real 0.061s	user 0.038s	sys 0.015s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":23741,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:42.714982 18892 maintenance_manager.cc:419] P 17f2ee1f59f84a25a5d1b4577041106d: Scheduling FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34): perf score=2.188937
I20260812 06:19:42.729640 18825 maintenance_manager.cc:643] P 17f2ee1f59f84a25a5d1b4577041106d: FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5412,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:42.730271 18892 maintenance_manager.cc:419] P 17f2ee1f59f84a25a5d1b4577041106d: Scheduling MajorDeltaCompactionOp(fe576f8bfde24159aa5d81d8db983e34): perf score=1.000000
I20260812 06:19:42.925988 18825 maintenance_manager.cc:643] P 17f2ee1f59f84a25a5d1b4577041106d: MajorDeltaCompactionOp(fe576f8bfde24159aa5d81d8db983e34) complete. Timing: real 0.196s	user 0.129s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774692,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":981,"lbm_read_time_us":13933,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29337,"lbm_writes_lt_1ms":543,"mutex_wait_us":48,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8832,"update_count":2500}
I20260812 06:19:42.926710 18892 maintenance_manager.cc:419] P 17f2ee1f59f84a25a5d1b4577041106d: Scheduling FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34): perf score=14.095187
I20260812 06:19:42.976202 18825 maintenance_manager.cc:643] P 17f2ee1f59f84a25a5d1b4577041106d: FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34) complete. Timing: real 0.049s	user 0.022s	sys 0.025s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22932,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:42.976768 18892 maintenance_manager.cc:419] P 17f2ee1f59f84a25a5d1b4577041106d: Scheduling FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34): perf score=2.188937
I20260812 06:19:42.988838 18825 maintenance_manager.cc:643] P 17f2ee1f59f84a25a5d1b4577041106d: FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34) complete. Timing: real 0.012s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4693,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:42.989467 18892 maintenance_manager.cc:419] P 17f2ee1f59f84a25a5d1b4577041106d: Scheduling MajorDeltaCompactionOp(fe576f8bfde24159aa5d81d8db983e34): perf score=1.000000
I20260812 06:19:43.149392 18825 maintenance_manager.cc:643] P 17f2ee1f59f84a25a5d1b4577041106d: MajorDeltaCompactionOp(fe576f8bfde24159aa5d81d8db983e34) complete. Timing: real 0.160s	user 0.117s	sys 0.037s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":186,"lbm_read_time_us":10142,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30062,"lbm_writes_lt_1ms":543,"mutex_wait_us":68,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5376,"update_count":2500}
I20260812 06:19:43.150138 18892 maintenance_manager.cc:419] P 17f2ee1f59f84a25a5d1b4577041106d: Scheduling FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34): perf score=14.095187
I20260812 06:19:43.207624 18825 maintenance_manager.cc:643] P 17f2ee1f59f84a25a5d1b4577041106d: FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34) complete. Timing: real 0.057s	user 0.022s	sys 0.032s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":26858,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:43.208214 18892 maintenance_manager.cc:419] P 17f2ee1f59f84a25a5d1b4577041106d: Scheduling FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34): perf score=2.188937
I20260812 06:19:43.220119 18825 maintenance_manager.cc:643] P 17f2ee1f59f84a25a5d1b4577041106d: FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4680,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:43.220563 18892 maintenance_manager.cc:419] P 17f2ee1f59f84a25a5d1b4577041106d: Scheduling MajorDeltaCompactionOp(fe576f8bfde24159aa5d81d8db983e34): perf score=1.000000
I20260812 06:19:43.380149 18825 maintenance_manager.cc:643] P 17f2ee1f59f84a25a5d1b4577041106d: MajorDeltaCompactionOp(fe576f8bfde24159aa5d81d8db983e34) complete. Timing: real 0.159s	user 0.130s	sys 0.020s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":890,"lbm_read_time_us":11293,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29934,"lbm_writes_lt_1ms":543,"mutex_wait_us":282,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9344,"update_count":2500}
I20260812 06:19:43.380811 18892 maintenance_manager.cc:419] P 17f2ee1f59f84a25a5d1b4577041106d: Scheduling FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34): perf score=14.095187
I20260812 06:19:43.431059 18825 maintenance_manager.cc:643] P 17f2ee1f59f84a25a5d1b4577041106d: FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34) complete. Timing: real 0.050s	user 0.027s	sys 0.020s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":21304,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:43.431617 18892 maintenance_manager.cc:419] P 17f2ee1f59f84a25a5d1b4577041106d: Scheduling FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34): perf score=2.188937
I20260812 06:19:43.446763 18825 maintenance_manager.cc:643] P 17f2ee1f59f84a25a5d1b4577041106d: FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34) complete. Timing: real 0.015s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5639,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:43.447319 18892 maintenance_manager.cc:419] P 17f2ee1f59f84a25a5d1b4577041106d: Scheduling MajorDeltaCompactionOp(fe576f8bfde24159aa5d81d8db983e34): perf score=1.000000
I20260812 06:19:43.608985 18825 maintenance_manager.cc:643] P 17f2ee1f59f84a25a5d1b4577041106d: MajorDeltaCompactionOp(fe576f8bfde24159aa5d81d8db983e34) complete. Timing: real 0.161s	user 0.117s	sys 0.032s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":184,"lbm_read_time_us":10266,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29776,"lbm_writes_lt_1ms":543,"mutex_wait_us":80,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2500}
I20260812 06:19:43.609638 18892 maintenance_manager.cc:419] P 17f2ee1f59f84a25a5d1b4577041106d: Scheduling FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34): perf score=14.095187
I20260812 06:19:43.662919 18825 maintenance_manager.cc:643] P 17f2ee1f59f84a25a5d1b4577041106d: FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34) complete. Timing: real 0.053s	user 0.030s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21536,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:43.663360 18892 maintenance_manager.cc:419] P 17f2ee1f59f84a25a5d1b4577041106d: Scheduling FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34): perf score=2.188937
I20260812 06:19:43.673358 18825 maintenance_manager.cc:643] P 17f2ee1f59f84a25a5d1b4577041106d: FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3816,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:43.673794 18892 maintenance_manager.cc:419] P 17f2ee1f59f84a25a5d1b4577041106d: Scheduling FlushMRSOp(fe576f8bfde24159aa5d81d8db983e34): perf score=1.000000
I20260812 06:19:43.705276 18825 maintenance_manager.cc:643] P 17f2ee1f59f84a25a5d1b4577041106d: FlushMRSOp(fe576f8bfde24159aa5d81d8db983e34) complete. Timing: real 0.031s	user 0.029s	sys 0.001s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":59,"dirs.run_cpu_time_us":245,"dirs.run_wall_time_us":1267,"drs_written":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1681,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:43.705897 18892 maintenance_manager.cc:419] P 17f2ee1f59f84a25a5d1b4577041106d: Scheduling LogGCOp(fe576f8bfde24159aa5d81d8db983e34): free 116849512 bytes of WAL
I20260812 06:19:43.706104 18825 log_reader.cc:385] T fe576f8bfde24159aa5d81d8db983e34: removed 12 log segments from log reader
I20260812 06:19:43.706162 18825 log.cc:1079] T fe576f8bfde24159aa5d81d8db983e34 P 17f2ee1f59f84a25a5d1b4577041106d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/fe576f8bfde24159aa5d81d8db983e34/wal-000000003 (ops 12-16)
I20260812 06:19:43.706213 18825 log.cc:1079] T fe576f8bfde24159aa5d81d8db983e34 P 17f2ee1f59f84a25a5d1b4577041106d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/fe576f8bfde24159aa5d81d8db983e34/wal-000000004 (ops 17-20)
I20260812 06:19:43.706278 18825 log.cc:1079] T fe576f8bfde24159aa5d81d8db983e34 P 17f2ee1f59f84a25a5d1b4577041106d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/fe576f8bfde24159aa5d81d8db983e34/wal-000000005 (ops 21-25)
I20260812 06:19:43.706319 18825 log.cc:1079] T fe576f8bfde24159aa5d81d8db983e34 P 17f2ee1f59f84a25a5d1b4577041106d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/fe576f8bfde24159aa5d81d8db983e34/wal-000000006 (ops 26-30)
I20260812 06:19:43.706357 18825 log.cc:1079] T fe576f8bfde24159aa5d81d8db983e34 P 17f2ee1f59f84a25a5d1b4577041106d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/fe576f8bfde24159aa5d81d8db983e34/wal-000000007 (ops 31-34)
I20260812 06:19:43.706394 18825 log.cc:1079] T fe576f8bfde24159aa5d81d8db983e34 P 17f2ee1f59f84a25a5d1b4577041106d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/fe576f8bfde24159aa5d81d8db983e34/wal-000000008 (ops 35-39)
I20260812 06:19:43.706431 18825 log.cc:1079] T fe576f8bfde24159aa5d81d8db983e34 P 17f2ee1f59f84a25a5d1b4577041106d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/fe576f8bfde24159aa5d81d8db983e34/wal-000000009 (ops 40-44)
I20260812 06:19:43.706470 18825 log.cc:1079] T fe576f8bfde24159aa5d81d8db983e34 P 17f2ee1f59f84a25a5d1b4577041106d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/fe576f8bfde24159aa5d81d8db983e34/wal-000000010 (ops 45-48)
I20260812 06:19:43.706506 18825 log.cc:1079] T fe576f8bfde24159aa5d81d8db983e34 P 17f2ee1f59f84a25a5d1b4577041106d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/fe576f8bfde24159aa5d81d8db983e34/wal-000000011 (ops 49-53)
I20260812 06:19:43.706543 18825 log.cc:1079] T fe576f8bfde24159aa5d81d8db983e34 P 17f2ee1f59f84a25a5d1b4577041106d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/fe576f8bfde24159aa5d81d8db983e34/wal-000000012 (ops 54-58)
I20260812 06:19:43.706579 18825 log.cc:1079] T fe576f8bfde24159aa5d81d8db983e34 P 17f2ee1f59f84a25a5d1b4577041106d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/fe576f8bfde24159aa5d81d8db983e34/wal-000000013 (ops 59-63)
I20260812 06:19:43.706615 18825 log.cc:1079] T fe576f8bfde24159aa5d81d8db983e34 P 17f2ee1f59f84a25a5d1b4577041106d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/fe576f8bfde24159aa5d81d8db983e34/wal-000000014 (ops 64-68)
I20260812 06:19:43.732084 18825 maintenance_manager.cc:643] P 17f2ee1f59f84a25a5d1b4577041106d: LogGCOp(fe576f8bfde24159aa5d81d8db983e34) complete. Timing: real 0.026s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:19:43.732478 18892 maintenance_manager.cc:419] P 17f2ee1f59f84a25a5d1b4577041106d: Scheduling UndoDeltaBlockGCOp(fe576f8bfde24159aa5d81d8db983e34): 472 bytes on disk
I20260812 06:19:43.732872 18825 maintenance_manager.cc:643] P 17f2ee1f59f84a25a5d1b4577041106d: UndoDeltaBlockGCOp(fe576f8bfde24159aa5d81d8db983e34) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4}
I20260812 06:19:43.733330 18892 maintenance_manager.cc:419] P 17f2ee1f59f84a25a5d1b4577041106d: Scheduling FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34): perf score=3.181125
I20260812 06:19:43.745329 18825 maintenance_manager.cc:643] P 17f2ee1f59f84a25a5d1b4577041106d: FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4594950,"delete_count":0,"lbm_write_time_us":4421,"lbm_writes_lt_1ms":115,"reinsert_count":0,"update_count":560}
I20260812 06:19:43.745712 18892 maintenance_manager.cc:419] P 17f2ee1f59f84a25a5d1b4577041106d: Scheduling LogGCOp(fe576f8bfde24159aa5d81d8db983e34): free 11564875 bytes of WAL
I20260812 06:19:43.746114 18825 log_reader.cc:385] T fe576f8bfde24159aa5d81d8db983e34: removed 1 log segments from log reader
I20260812 06:19:43.746160 18825 log.cc:1079] T fe576f8bfde24159aa5d81d8db983e34 P 17f2ee1f59f84a25a5d1b4577041106d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/fe576f8bfde24159aa5d81d8db983e34/wal-000000015 (ops 69-72)
I20260812 06:19:43.748495 18825 maintenance_manager.cc:643] P 17f2ee1f59f84a25a5d1b4577041106d: LogGCOp(fe576f8bfde24159aa5d81d8db983e34) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:19:43.748781 18892 maintenance_manager.cc:419] P 17f2ee1f59f84a25a5d1b4577041106d: Scheduling FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34): perf score=2.188937
I20260812 06:19:43.758682 18825 maintenance_manager.cc:643] P 17f2ee1f59f84a25a5d1b4577041106d: FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3610355,"delete_count":0,"lbm_write_time_us":3525,"lbm_writes_lt_1ms":91,"reinsert_count":0,"update_count":440}
I20260812 06:19:43.759289 18892 maintenance_manager.cc:419] P 17f2ee1f59f84a25a5d1b4577041106d: Scheduling MajorDeltaCompactionOp(fe576f8bfde24159aa5d81d8db983e34): perf score=1.000000
I20260812 06:19:43.972807 18825 maintenance_manager.cc:643] P 17f2ee1f59f84a25a5d1b4577041106d: MajorDeltaCompactionOp(fe576f8bfde24159aa5d81d8db983e34) complete. Timing: real 0.213s	user 0.134s	sys 0.079s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979737,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":240,"lbm_read_time_us":15779,"lbm_reads_lt_1ms":774,"lbm_write_time_us":37271,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":3200,"thread_start_us":80,"threads_started":1,"update_count":3500}
I20260812 06:19:43.973863 18892 maintenance_manager.cc:419] P 17f2ee1f59f84a25a5d1b4577041106d: Scheduling FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34): perf score=18.063937
I20260812 06:19:44.034355 18825 maintenance_manager.cc:643] P 17f2ee1f59f84a25a5d1b4577041106d: FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34) complete. Timing: real 0.060s	user 0.043s	sys 0.016s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":26815,"lbm_writes_lt_1ms":503,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2500}
I20260812 06:19:44.035094 18892 maintenance_manager.cc:419] P 17f2ee1f59f84a25a5d1b4577041106d: Scheduling FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34): perf score=2.188937
I20260812 06:19:44.066349 18825 maintenance_manager.cc:643] P 17f2ee1f59f84a25a5d1b4577041106d: FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34) complete. Timing: real 0.031s	user 0.007s	sys 0.009s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6532,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:44.066926 18892 maintenance_manager.cc:419] P 17f2ee1f59f84a25a5d1b4577041106d: Scheduling FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34): perf score=2.188937
I20260812 06:19:44.077105 18825 maintenance_manager.cc:643] P 17f2ee1f59f84a25a5d1b4577041106d: FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34) complete. Timing: real 0.010s	user 0.001s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4122,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:44.077560 18892 maintenance_manager.cc:419] P 17f2ee1f59f84a25a5d1b4577041106d: Scheduling MajorDeltaCompactionOp(fe576f8bfde24159aa5d81d8db983e34): perf score=1.000000
I20260812 06:19:44.267817 18825 maintenance_manager.cc:643] P 17f2ee1f59f84a25a5d1b4577041106d: MajorDeltaCompactionOp(fe576f8bfde24159aa5d81d8db983e34) complete. Timing: real 0.190s	user 0.146s	sys 0.044s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":32979633,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":299,"lbm_read_time_us":14342,"lbm_reads_lt_1ms":773,"lbm_write_time_us":38814,"lbm_writes_lt_1ms":743,"mutex_wait_us":119,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":3500}
I20260812 06:19:44.268548 18892 maintenance_manager.cc:419] P 17f2ee1f59f84a25a5d1b4577041106d: Scheduling FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34): perf score=14.095187
I20260812 06:19:44.319679 18825 maintenance_manager.cc:643] P 17f2ee1f59f84a25a5d1b4577041106d: FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34) complete. Timing: real 0.051s	user 0.046s	sys 0.003s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22467,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:44.321024 18892 maintenance_manager.cc:419] P 17f2ee1f59f84a25a5d1b4577041106d: Scheduling FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34): perf score=2.188937
I20260812 06:19:44.331745 18825 maintenance_manager.cc:643] P 17f2ee1f59f84a25a5d1b4577041106d: FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34) complete. Timing: real 0.010s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4220,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:44.332418 18892 maintenance_manager.cc:419] P 17f2ee1f59f84a25a5d1b4577041106d: Scheduling MajorDeltaCompactionOp(fe576f8bfde24159aa5d81d8db983e34): perf score=1.000000
I20260812 06:19:44.495079 18825 maintenance_manager.cc:643] P 17f2ee1f59f84a25a5d1b4577041106d: MajorDeltaCompactionOp(fe576f8bfde24159aa5d81d8db983e34) complete. Timing: real 0.162s	user 0.124s	sys 0.028s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":161,"lbm_read_time_us":11235,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28948,"lbm_writes_lt_1ms":543,"mutex_wait_us":42,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:19:44.495635 18892 maintenance_manager.cc:419] P 17f2ee1f59f84a25a5d1b4577041106d: Scheduling FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34): perf score=14.095187
I20260812 06:19:44.555419 18825 maintenance_manager.cc:643] P 17f2ee1f59f84a25a5d1b4577041106d: FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34) complete. Timing: real 0.060s	user 0.022s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21975,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:44.555902 18892 maintenance_manager.cc:419] P 17f2ee1f59f84a25a5d1b4577041106d: Scheduling FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34): perf score=2.188937
I20260812 06:19:44.566969 18825 maintenance_manager.cc:643] P 17f2ee1f59f84a25a5d1b4577041106d: FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3948,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:44.567588 18892 maintenance_manager.cc:419] P 17f2ee1f59f84a25a5d1b4577041106d: Scheduling MajorDeltaCompactionOp(fe576f8bfde24159aa5d81d8db983e34): perf score=1.000000
I20260812 06:19:44.758172 18825 maintenance_manager.cc:643] P 17f2ee1f59f84a25a5d1b4577041106d: MajorDeltaCompactionOp(fe576f8bfde24159aa5d81d8db983e34) complete. Timing: real 0.190s	user 0.147s	sys 0.039s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":411,"lbm_read_time_us":11678,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29060,"lbm_writes_lt_1ms":543,"mutex_wait_us":40,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5376,"update_count":2500}
I20260812 06:19:44.758894 18892 maintenance_manager.cc:419] P 17f2ee1f59f84a25a5d1b4577041106d: Scheduling FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34): perf score=14.095187
I20260812 06:19:44.815577 18825 maintenance_manager.cc:643] P 17f2ee1f59f84a25a5d1b4577041106d: FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34) complete. Timing: real 0.057s	user 0.033s	sys 0.020s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24881,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:44.816154 18892 maintenance_manager.cc:419] P 17f2ee1f59f84a25a5d1b4577041106d: Scheduling MajorDeltaCompactionOp(fe576f8bfde24159aa5d81d8db983e34): perf score=1.000000
I20260812 06:19:44.972438 18825 maintenance_manager.cc:643] P 17f2ee1f59f84a25a5d1b4577041106d: MajorDeltaCompactionOp(fe576f8bfde24159aa5d81d8db983e34) complete. Timing: real 0.156s	user 0.112s	sys 0.044s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672158,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":661,"lbm_read_time_us":10107,"lbm_reads_lt_1ms":463,"lbm_write_time_us":24628,"lbm_writes_lt_1ms":443,"mutex_wait_us":101,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":2000}
I20260812 06:19:44.973150 18892 maintenance_manager.cc:419] P 17f2ee1f59f84a25a5d1b4577041106d: Scheduling FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34): perf score=14.095187
I20260812 06:19:45.020855 18825 maintenance_manager.cc:643] P 17f2ee1f59f84a25a5d1b4577041106d: FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34) complete. Timing: real 0.048s	user 0.032s	sys 0.012s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21218,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:45.021394 18892 maintenance_manager.cc:419] P 17f2ee1f59f84a25a5d1b4577041106d: Scheduling FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34): perf score=2.188937
I20260812 06:19:45.033754 18825 maintenance_manager.cc:643] P 17f2ee1f59f84a25a5d1b4577041106d: FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34) complete. Timing: real 0.012s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4409,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:45.034448 18892 maintenance_manager.cc:419] P 17f2ee1f59f84a25a5d1b4577041106d: Scheduling FlushMRSOp(fe576f8bfde24159aa5d81d8db983e34): perf score=1.000000
I20260812 06:19:45.069152 18825 maintenance_manager.cc:643] P 17f2ee1f59f84a25a5d1b4577041106d: FlushMRSOp(fe576f8bfde24159aa5d81d8db983e34) complete. Timing: real 0.035s	user 0.033s	sys 0.000s Metrics: {"bytes_written":1152514,"cfile_init":1,"dirs.queue_time_us":508,"dirs.run_cpu_time_us":233,"dirs.run_wall_time_us":1301,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2038,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:45.069868 18892 maintenance_manager.cc:419] P 17f2ee1f59f84a25a5d1b4577041106d: Scheduling LogGCOp(fe576f8bfde24159aa5d81d8db983e34): free 108082405 bytes of WAL
I20260812 06:19:45.070111 18825 log_reader.cc:385] T fe576f8bfde24159aa5d81d8db983e34: removed 11 log segments from log reader
I20260812 06:19:45.070154 18825 log.cc:1079] T fe576f8bfde24159aa5d81d8db983e34 P 17f2ee1f59f84a25a5d1b4577041106d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/fe576f8bfde24159aa5d81d8db983e34/wal-000000016 (ops 73-77)
I20260812 06:19:45.070225 18825 log.cc:1079] T fe576f8bfde24159aa5d81d8db983e34 P 17f2ee1f59f84a25a5d1b4577041106d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/fe576f8bfde24159aa5d81d8db983e34/wal-000000017 (ops 78-82)
I20260812 06:19:45.070269 18825 log.cc:1079] T fe576f8bfde24159aa5d81d8db983e34 P 17f2ee1f59f84a25a5d1b4577041106d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/fe576f8bfde24159aa5d81d8db983e34/wal-000000018 (ops 83-86)
I20260812 06:19:45.070299 18825 log.cc:1079] T fe576f8bfde24159aa5d81d8db983e34 P 17f2ee1f59f84a25a5d1b4577041106d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/fe576f8bfde24159aa5d81d8db983e34/wal-000000019 (ops 87-91)
I20260812 06:19:45.070335 18825 log.cc:1079] T fe576f8bfde24159aa5d81d8db983e34 P 17f2ee1f59f84a25a5d1b4577041106d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/fe576f8bfde24159aa5d81d8db983e34/wal-000000020 (ops 92-96)
I20260812 06:19:45.070377 18825 log.cc:1079] T fe576f8bfde24159aa5d81d8db983e34 P 17f2ee1f59f84a25a5d1b4577041106d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/fe576f8bfde24159aa5d81d8db983e34/wal-000000021 (ops 97-100)
I20260812 06:19:45.070420 18825 log.cc:1079] T fe576f8bfde24159aa5d81d8db983e34 P 17f2ee1f59f84a25a5d1b4577041106d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/fe576f8bfde24159aa5d81d8db983e34/wal-000000022 (ops 101-105)
I20260812 06:19:45.070461 18825 log.cc:1079] T fe576f8bfde24159aa5d81d8db983e34 P 17f2ee1f59f84a25a5d1b4577041106d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/fe576f8bfde24159aa5d81d8db983e34/wal-000000023 (ops 106-110)
I20260812 06:19:45.070501 18825 log.cc:1079] T fe576f8bfde24159aa5d81d8db983e34 P 17f2ee1f59f84a25a5d1b4577041106d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/fe576f8bfde24159aa5d81d8db983e34/wal-000000024 (ops 111-115)
I20260812 06:19:45.070541 18825 log.cc:1079] T fe576f8bfde24159aa5d81d8db983e34 P 17f2ee1f59f84a25a5d1b4577041106d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/fe576f8bfde24159aa5d81d8db983e34/wal-000000025 (ops 116-120)
I20260812 06:19:45.070581 18825 log.cc:1079] T fe576f8bfde24159aa5d81d8db983e34 P 17f2ee1f59f84a25a5d1b4577041106d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/fe576f8bfde24159aa5d81d8db983e34/wal-000000026 (ops 121-124)
I20260812 06:19:45.093362 18825 maintenance_manager.cc:643] P 17f2ee1f59f84a25a5d1b4577041106d: LogGCOp(fe576f8bfde24159aa5d81d8db983e34) complete. Timing: real 0.023s	user 0.000s	sys 0.020s Metrics: {}
I20260812 06:19:45.094532 18892 maintenance_manager.cc:419] P 17f2ee1f59f84a25a5d1b4577041106d: Scheduling FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34): perf score=3.181125
I20260812 06:19:45.119107 18825 maintenance_manager.cc:643] P 17f2ee1f59f84a25a5d1b4577041106d: FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34) complete. Timing: real 0.024s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4307779,"delete_count":0,"lbm_write_time_us":5565,"lbm_writes_lt_1ms":108,"reinsert_count":0,"update_count":525}
I20260812 06:19:45.119546 18892 maintenance_manager.cc:419] P 17f2ee1f59f84a25a5d1b4577041106d: Scheduling UndoDeltaBlockGCOp(fe576f8bfde24159aa5d81d8db983e34): 450 bytes on disk
I20260812 06:19:45.119956 18825 maintenance_manager.cc:643] P 17f2ee1f59f84a25a5d1b4577041106d: UndoDeltaBlockGCOp(fe576f8bfde24159aa5d81d8db983e34) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4}
I20260812 06:19:45.120457 18892 maintenance_manager.cc:419] P 17f2ee1f59f84a25a5d1b4577041106d: Scheduling FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34): perf score=2.188937
I20260812 06:19:45.130584 18825 maintenance_manager.cc:643] P 17f2ee1f59f84a25a5d1b4577041106d: FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3897534,"delete_count":0,"lbm_write_time_us":3830,"lbm_writes_lt_1ms":98,"reinsert_count":0,"update_count":475}
I20260812 06:19:45.131309 18892 maintenance_manager.cc:419] P 17f2ee1f59f84a25a5d1b4577041106d: Scheduling MajorDeltaCompactionOp(fe576f8bfde24159aa5d81d8db983e34): perf score=1.000000
I20260812 06:19:45.377573 18825 maintenance_manager.cc:643] P 17f2ee1f59f84a25a5d1b4577041106d: MajorDeltaCompactionOp(fe576f8bfde24159aa5d81d8db983e34) complete. Timing: real 0.246s	user 0.160s	sys 0.075s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979747,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":2772,"dirs.run_cpu_time_us":603,"dirs.run_wall_time_us":2962,"lbm_read_time_us":15468,"lbm_reads_lt_1ms":774,"lbm_write_time_us":39842,"lbm_writes_lt_1ms":743,"mutex_wait_us":2194,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":3500}
I20260812 06:19:45.378257 18892 maintenance_manager.cc:419] P 17f2ee1f59f84a25a5d1b4577041106d: Scheduling FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34): perf score=18.063937
I20260812 06:19:45.450060 18825 maintenance_manager.cc:643] P 17f2ee1f59f84a25a5d1b4577041106d: FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34) complete. Timing: real 0.072s	user 0.029s	sys 0.042s Metrics: {"bytes_written":20512311,"delete_count":0,"lbm_write_time_us":28649,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:45.450644 18892 maintenance_manager.cc:419] P 17f2ee1f59f84a25a5d1b4577041106d: Scheduling FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34): perf score=2.188937
I20260812 06:19:45.466714 18825 maintenance_manager.cc:643] P 17f2ee1f59f84a25a5d1b4577041106d: FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34) complete. Timing: real 0.016s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5217,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:45.467252 18892 maintenance_manager.cc:419] P 17f2ee1f59f84a25a5d1b4577041106d: Scheduling MajorDeltaCompactionOp(fe576f8bfde24159aa5d81d8db983e34): perf score=1.000000
I20260812 06:19:45.678292 18825 maintenance_manager.cc:643] P 17f2ee1f59f84a25a5d1b4577041106d: MajorDeltaCompactionOp(fe576f8bfde24159aa5d81d8db983e34) complete. Timing: real 0.211s	user 0.147s	sys 0.063s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877098,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":985,"lbm_read_time_us":15762,"lbm_reads_lt_1ms":668,"lbm_write_time_us":36244,"lbm_writes_lt_1ms":643,"mutex_wait_us":299,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":9088,"update_count":3000}
I20260812 06:19:45.679179 18892 maintenance_manager.cc:419] P 17f2ee1f59f84a25a5d1b4577041106d: Scheduling FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34): perf score=14.095187
I20260812 06:19:45.732569 18825 maintenance_manager.cc:643] P 17f2ee1f59f84a25a5d1b4577041106d: FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34) complete. Timing: real 0.053s	user 0.023s	sys 0.025s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22006,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:45.733317 18892 maintenance_manager.cc:419] P 17f2ee1f59f84a25a5d1b4577041106d: Scheduling FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34): perf score=3.181125
I20260812 06:19:45.749378 18825 maintenance_manager.cc:643] P 17f2ee1f59f84a25a5d1b4577041106d: FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34) complete. Timing: real 0.016s	user 0.006s	sys 0.007s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":6411,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:45.749866 18892 maintenance_manager.cc:419] P 17f2ee1f59f84a25a5d1b4577041106d: Scheduling FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34): perf score=2.188937
I20260812 06:19:45.759367 18825 maintenance_manager.cc:643] P 17f2ee1f59f84a25a5d1b4577041106d: FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3653,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:45.759804 18892 maintenance_manager.cc:419] P 17f2ee1f59f84a25a5d1b4577041106d: Scheduling MajorDeltaCompactionOp(fe576f8bfde24159aa5d81d8db983e34): perf score=1.000000
I20260812 06:19:45.964336 18825 maintenance_manager.cc:643] P 17f2ee1f59f84a25a5d1b4577041106d: MajorDeltaCompactionOp(fe576f8bfde24159aa5d81d8db983e34) complete. Timing: real 0.204s	user 0.128s	sys 0.076s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877206,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1092,"lbm_read_time_us":13832,"lbm_reads_lt_1ms":673,"lbm_write_time_us":35014,"lbm_writes_lt_1ms":643,"mutex_wait_us":31,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":4352,"update_count":3000}
I20260812 06:19:45.965176 18892 maintenance_manager.cc:419] P 17f2ee1f59f84a25a5d1b4577041106d: Scheduling FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34): perf score=14.095187
I20260812 06:19:46.015817 18825 maintenance_manager.cc:643] P 17f2ee1f59f84a25a5d1b4577041106d: FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34) complete. Timing: real 0.050s	user 0.024s	sys 0.024s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":22936,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:46.016692 18892 maintenance_manager.cc:419] P 17f2ee1f59f84a25a5d1b4577041106d: Scheduling FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34): perf score=2.188937
I20260812 06:19:46.046388 18825 maintenance_manager.cc:643] P 17f2ee1f59f84a25a5d1b4577041106d: FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34) complete. Timing: real 0.029s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6145,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:46.046900 18892 maintenance_manager.cc:419] P 17f2ee1f59f84a25a5d1b4577041106d: Scheduling FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34): perf score=2.188937
I20260812 06:19:46.057591 18825 maintenance_manager.cc:643] P 17f2ee1f59f84a25a5d1b4577041106d: FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3998,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:46.058171 18892 maintenance_manager.cc:419] P 17f2ee1f59f84a25a5d1b4577041106d: Scheduling MajorDeltaCompactionOp(fe576f8bfde24159aa5d81d8db983e34): perf score=1.000000
I20260812 06:19:46.261122 18825 maintenance_manager.cc:643] P 17f2ee1f59f84a25a5d1b4577041106d: MajorDeltaCompactionOp(fe576f8bfde24159aa5d81d8db983e34) complete. Timing: real 0.203s	user 0.127s	sys 0.075s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877218,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1027,"lbm_read_time_us":14157,"lbm_reads_lt_1ms":673,"lbm_write_time_us":33011,"lbm_writes_lt_1ms":643,"mutex_wait_us":31,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":14208,"update_count":3000}
I20260812 06:19:46.261997 18892 maintenance_manager.cc:419] P 17f2ee1f59f84a25a5d1b4577041106d: Scheduling FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34): perf score=14.095187
I20260812 06:19:46.309875 18825 maintenance_manager.cc:643] P 17f2ee1f59f84a25a5d1b4577041106d: FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34) complete. Timing: real 0.048s	user 0.031s	sys 0.017s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20939,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:46.310521 18892 maintenance_manager.cc:419] P 17f2ee1f59f84a25a5d1b4577041106d: Scheduling FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34): perf score=2.188937
I20260812 06:19:46.329001 18825 maintenance_manager.cc:643] P 17f2ee1f59f84a25a5d1b4577041106d: FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34) complete. Timing: real 0.018s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6512,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:46.329461 18892 maintenance_manager.cc:419] P 17f2ee1f59f84a25a5d1b4577041106d: Scheduling MajorDeltaCompactionOp(fe576f8bfde24159aa5d81d8db983e34): perf score=1.000000
I20260812 06:19:46.493644 18825 maintenance_manager.cc:643] P 17f2ee1f59f84a25a5d1b4577041106d: MajorDeltaCompactionOp(fe576f8bfde24159aa5d81d8db983e34) complete. Timing: real 0.164s	user 0.120s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1160,"lbm_read_time_us":10264,"lbm_reads_lt_1ms":564,"lbm_write_time_us":27572,"lbm_writes_lt_1ms":543,"mutex_wait_us":286,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9856,"update_count":2500}
I20260812 06:19:46.494372 18892 maintenance_manager.cc:419] P 17f2ee1f59f84a25a5d1b4577041106d: Scheduling FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34): perf score=14.095187
I20260812 06:19:46.551286 18825 maintenance_manager.cc:643] P 17f2ee1f59f84a25a5d1b4577041106d: FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34) complete. Timing: real 0.057s	user 0.053s	sys 0.000s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":23366,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:46.551856 18892 maintenance_manager.cc:419] P 17f2ee1f59f84a25a5d1b4577041106d: Scheduling FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34): perf score=2.188937
I20260812 06:19:46.563064 18825 maintenance_manager.cc:643] P 17f2ee1f59f84a25a5d1b4577041106d: FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34) complete. Timing: real 0.011s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4404,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:46.563709 18892 maintenance_manager.cc:419] P 17f2ee1f59f84a25a5d1b4577041106d: Scheduling FlushMRSOp(fe576f8bfde24159aa5d81d8db983e34): perf score=1.000000
I20260812 06:19:46.595170 18825 maintenance_manager.cc:643] P 17f2ee1f59f84a25a5d1b4577041106d: FlushMRSOp(fe576f8bfde24159aa5d81d8db983e34) complete. Timing: real 0.031s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1234475,"cfile_init":1,"dirs.queue_time_us":61,"dirs.run_cpu_time_us":208,"dirs.run_wall_time_us":1453,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1988,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:46.595854 18892 maintenance_manager.cc:419] P 17f2ee1f59f84a25a5d1b4577041106d: Scheduling LogGCOp(fe576f8bfde24159aa5d81d8db983e34): free 125616901 bytes of WAL
I20260812 06:19:46.596088 18825 log_reader.cc:385] T fe576f8bfde24159aa5d81d8db983e34: removed 13 log segments from log reader
I20260812 06:19:46.596134 18825 log.cc:1079] T fe576f8bfde24159aa5d81d8db983e34 P 17f2ee1f59f84a25a5d1b4577041106d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/fe576f8bfde24159aa5d81d8db983e34/wal-000000027 (ops 125-129)
I20260812 06:19:46.596170 18825 log.cc:1079] T fe576f8bfde24159aa5d81d8db983e34 P 17f2ee1f59f84a25a5d1b4577041106d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/fe576f8bfde24159aa5d81d8db983e34/wal-000000028 (ops 130-134)
I20260812 06:19:46.596240 18825 log.cc:1079] T fe576f8bfde24159aa5d81d8db983e34 P 17f2ee1f59f84a25a5d1b4577041106d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/fe576f8bfde24159aa5d81d8db983e34/wal-000000029 (ops 135-138)
I20260812 06:19:46.596282 18825 log.cc:1079] T fe576f8bfde24159aa5d81d8db983e34 P 17f2ee1f59f84a25a5d1b4577041106d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/fe576f8bfde24159aa5d81d8db983e34/wal-000000030 (ops 139-143)
I20260812 06:19:46.596323 18825 log.cc:1079] T fe576f8bfde24159aa5d81d8db983e34 P 17f2ee1f59f84a25a5d1b4577041106d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/fe576f8bfde24159aa5d81d8db983e34/wal-000000031 (ops 144-148)
I20260812 06:19:46.596364 18825 log.cc:1079] T fe576f8bfde24159aa5d81d8db983e34 P 17f2ee1f59f84a25a5d1b4577041106d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/fe576f8bfde24159aa5d81d8db983e34/wal-000000032 (ops 149-153)
I20260812 06:19:46.596405 18825 log.cc:1079] T fe576f8bfde24159aa5d81d8db983e34 P 17f2ee1f59f84a25a5d1b4577041106d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/fe576f8bfde24159aa5d81d8db983e34/wal-000000033 (ops 154-158)
I20260812 06:19:46.596427 18825 log.cc:1079] T fe576f8bfde24159aa5d81d8db983e34 P 17f2ee1f59f84a25a5d1b4577041106d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/fe576f8bfde24159aa5d81d8db983e34/wal-000000034 (ops 159-162)
I20260812 06:19:46.596467 18825 log.cc:1079] T fe576f8bfde24159aa5d81d8db983e34 P 17f2ee1f59f84a25a5d1b4577041106d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/fe576f8bfde24159aa5d81d8db983e34/wal-000000035 (ops 163-167)
I20260812 06:19:46.596503 18825 log.cc:1079] T fe576f8bfde24159aa5d81d8db983e34 P 17f2ee1f59f84a25a5d1b4577041106d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/fe576f8bfde24159aa5d81d8db983e34/wal-000000036 (ops 168-172)
I20260812 06:19:46.596544 18825 log.cc:1079] T fe576f8bfde24159aa5d81d8db983e34 P 17f2ee1f59f84a25a5d1b4577041106d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/fe576f8bfde24159aa5d81d8db983e34/wal-000000037 (ops 173-176)
I20260812 06:19:46.596583 18825 log.cc:1079] T fe576f8bfde24159aa5d81d8db983e34 P 17f2ee1f59f84a25a5d1b4577041106d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/fe576f8bfde24159aa5d81d8db983e34/wal-000000038 (ops 177-181)
I20260812 06:19:46.596624 18825 log.cc:1079] T fe576f8bfde24159aa5d81d8db983e34 P 17f2ee1f59f84a25a5d1b4577041106d: Deleting log segment in path: /tmp/dist-test-taskyv8LzF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576309717-18470-0/minicluster-data/ts-0-root/wals/fe576f8bfde24159aa5d81d8db983e34/wal-000000039 (ops 182-186)
I20260812 06:19:46.622789 18825 maintenance_manager.cc:643] P 17f2ee1f59f84a25a5d1b4577041106d: LogGCOp(fe576f8bfde24159aa5d81d8db983e34) complete. Timing: real 0.027s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:19:46.623296 18892 maintenance_manager.cc:419] P 17f2ee1f59f84a25a5d1b4577041106d: Scheduling FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34): perf score=2.188937
I20260812 06:19:46.637184 18825 maintenance_manager.cc:643] P 17f2ee1f59f84a25a5d1b4577041106d: FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34) complete. Timing: real 0.014s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4448,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:46.637614 18892 maintenance_manager.cc:419] P 17f2ee1f59f84a25a5d1b4577041106d: Scheduling FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34): perf score=2.188937
I20260812 06:19:46.648346 18825 maintenance_manager.cc:643] P 17f2ee1f59f84a25a5d1b4577041106d: FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4328,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:46.648833 18892 maintenance_manager.cc:419] P 17f2ee1f59f84a25a5d1b4577041106d: Scheduling UndoDeltaBlockGCOp(fe576f8bfde24159aa5d81d8db983e34): 472 bytes on disk
I20260812 06:19:46.649458 18825 maintenance_manager.cc:643] P 17f2ee1f59f84a25a5d1b4577041106d: UndoDeltaBlockGCOp(fe576f8bfde24159aa5d81d8db983e34) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":118,"lbm_reads_lt_1ms":4}
I20260812 06:19:46.650470 18892 maintenance_manager.cc:419] P 17f2ee1f59f84a25a5d1b4577041106d: Scheduling MajorDeltaCompactionOp(fe576f8bfde24159aa5d81d8db983e34): perf score=1.000000
I20260812 06:19:46.883744 18825 maintenance_manager.cc:643] P 17f2ee1f59f84a25a5d1b4577041106d: MajorDeltaCompactionOp(fe576f8bfde24159aa5d81d8db983e34) complete. Timing: real 0.233s	user 0.143s	sys 0.088s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979752,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1748,"lbm_read_time_us":15898,"lbm_reads_lt_1ms":774,"lbm_write_time_us":43212,"lbm_writes_lt_1ms":743,"mutex_wait_us":42,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":7808,"thread_start_us":77,"threads_started":1,"update_count":3500}
I20260812 06:19:46.884400 18892 maintenance_manager.cc:419] P 17f2ee1f59f84a25a5d1b4577041106d: Scheduling FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34): perf score=18.063937
I20260812 06:19:46.936620 18470 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.842s	user 1.868s	sys 0.113s
I20260812 06:19:46.947402 18825 maintenance_manager.cc:643] P 17f2ee1f59f84a25a5d1b4577041106d: FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34) complete. Timing: real 0.063s	user 0.026s	sys 0.035s Metrics: {"bytes_written":20512319,"delete_count":0,"lbm_write_time_us":31373,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":501,"reinsert_count":0,"update_count":2500}
I20260812 06:19:46.948050 18892 maintenance_manager.cc:419] P 17f2ee1f59f84a25a5d1b4577041106d: Scheduling FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34): perf score=2.188937
I20260812 06:19:46.958400 18825 maintenance_manager.cc:643] P 17f2ee1f59f84a25a5d1b4577041106d: FlushDeltaMemStoresOp(fe576f8bfde24159aa5d81d8db983e34) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3994,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:46.958873 18892 maintenance_manager.cc:419] P 17f2ee1f59f84a25a5d1b4577041106d: Scheduling MajorDeltaCompactionOp(fe576f8bfde24159aa5d81d8db983e34): perf score=1.000000
I20260812 06:19:46.966018 18470 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.029s	user 0.005s	sys 0.000s
I20260812 06:19:46.966588 18470 tablet_server.cc:179] TabletServer@127.18.9.129:0 shutting down...
I20260812 06:19:47.108384 18825 maintenance_manager.cc:643] P 17f2ee1f59f84a25a5d1b4577041106d: MajorDeltaCompactionOp(fe576f8bfde24159aa5d81d8db983e34) complete. Timing: real 0.149s	user 0.121s	sys 0.027s Metrics: {"cfile_cache_hit":30,"cfile_cache_hit_bytes":4262390,"cfile_cache_miss":602,"cfile_cache_miss_bytes":24614715,"cfile_init":4,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":923,"lbm_read_time_us":10413,"lbm_reads_lt_1ms":618,"lbm_write_time_us":28094,"lbm_writes_lt_1ms":643,"mutex_wait_us":190,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":21248,"update_count":3000}
I20260812 06:19:47.109213 18470 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:47.109560 18470 tablet_replica.cc:333] T fe576f8bfde24159aa5d81d8db983e34 P 17f2ee1f59f84a25a5d1b4577041106d: stopping tablet replica
I20260812 06:19:47.109767 18470 raft_consensus.cc:2243] T fe576f8bfde24159aa5d81d8db983e34 P 17f2ee1f59f84a25a5d1b4577041106d [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:47.110030 18470 raft_consensus.cc:2272] T fe576f8bfde24159aa5d81d8db983e34 P 17f2ee1f59f84a25a5d1b4577041106d [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:47.114416 18470 tablet_server.cc:196] TabletServer@127.18.9.129:0 shutdown complete.
I20260812 06:19:47.160238 18470 master.cc:562] Master@127.18.9.190:41639 shutting down...
I20260812 06:19:47.164014 18470 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 11cec9012b1a4cb48fa8ab563d2fd0f1 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:47.164184 18470 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 11cec9012b1a4cb48fa8ab563d2fd0f1 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:47.164235 18470 tablet_replica.cc:333] T 00000000000000000000000000000000 P 11cec9012b1a4cb48fa8ab563d2fd0f1: stopping tablet replica
I20260812 06:19:47.176828 18470 master.cc:584] Master@127.18.9.190:41639 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5384 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10957 ms total)

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