[==========] 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:18:43.317292 13591 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.13.69.254:37785
I20260812 06:18:43.318289 13591 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:18:43.318897 13591 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:18:43.325738 13591 server_base.cc:1061] running on GCE node
W20260812 06:18:43.325832 13602 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:18:43.326062 13598 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:18:43.326148 13597 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:18:43.326695 13591 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:43.326787 13591 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:18:43.326813 13591 hybrid_clock.cc:648] HybridClock initialized: now 1786515523326812 us; error 0 us; skew 500 ppm
I20260812 06:18:43.328569 13591 webserver.cc:533] Webserver started at http://127.13.69.254:36285/ using document root <none> and password file <none>
I20260812 06:18:43.329150 13591 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:43.329211 13591 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:43.329401 13591 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:43.331010 13591 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523306816-13591-0/minicluster-data/master-0-root/instance:
uuid: "d8debbb357b8433fa1583798fb7c144a"
format_stamp: "Formatted at 2026-08-12 06:18:43 on dist-test-slave-x5fp"
I20260812 06:18:43.334455 13591 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.005s	sys 0.000s
I20260812 06:18:43.336520 13610 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:18:43.337575 13591 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:43.337713 13591 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523306816-13591-0/minicluster-data/master-0-root
uuid: "d8debbb357b8433fa1583798fb7c144a"
format_stamp: "Formatted at 2026-08-12 06:18:43 on dist-test-slave-x5fp"
I20260812 06:18:43.337818 13591 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523306816-13591-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523306816-13591-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523306816-13591-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:18:43.357832 13591 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:43.358515 13591 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:18:43.358711 13591 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:43.366490 13591 rpc_server.cc:307] RPC server started. Bound to: 127.13.69.254:37785
I20260812 06:18:43.366500 13695 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.13.69.254:37785 every 8 connection(s)
I20260812 06:18:43.368770 13696 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:18:43.374037 13696 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P d8debbb357b8433fa1583798fb7c144a: Bootstrap starting.
I20260812 06:18:43.376267 13696 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P d8debbb357b8433fa1583798fb7c144a: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:43.377141 13696 log.cc:826] T 00000000000000000000000000000000 P d8debbb357b8433fa1583798fb7c144a: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:43.378753 13696 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P d8debbb357b8433fa1583798fb7c144a: No bootstrap required, opened a new log
I20260812 06:18:43.381521 13696 raft_consensus.cc:359] T 00000000000000000000000000000000 P d8debbb357b8433fa1583798fb7c144a [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d8debbb357b8433fa1583798fb7c144a" member_type: VOTER }
I20260812 06:18:43.381676 13696 raft_consensus.cc:385] T 00000000000000000000000000000000 P d8debbb357b8433fa1583798fb7c144a [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:43.381717 13696 raft_consensus.cc:740] T 00000000000000000000000000000000 P d8debbb357b8433fa1583798fb7c144a [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: d8debbb357b8433fa1583798fb7c144a, State: Initialized, Role: FOLLOWER
I20260812 06:18:43.382313 13696 consensus_queue.cc:260] T 00000000000000000000000000000000 P d8debbb357b8433fa1583798fb7c144a [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: "d8debbb357b8433fa1583798fb7c144a" member_type: VOTER }
I20260812 06:18:43.382459 13696 raft_consensus.cc:399] T 00000000000000000000000000000000 P d8debbb357b8433fa1583798fb7c144a [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:43.382506 13696 raft_consensus.cc:493] T 00000000000000000000000000000000 P d8debbb357b8433fa1583798fb7c144a [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:43.382586 13696 raft_consensus.cc:3060] T 00000000000000000000000000000000 P d8debbb357b8433fa1583798fb7c144a [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:43.383342 13696 raft_consensus.cc:515] T 00000000000000000000000000000000 P d8debbb357b8433fa1583798fb7c144a [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d8debbb357b8433fa1583798fb7c144a" member_type: VOTER }
I20260812 06:18:43.383718 13696 leader_election.cc:304] T 00000000000000000000000000000000 P d8debbb357b8433fa1583798fb7c144a [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: d8debbb357b8433fa1583798fb7c144a; no voters: 
I20260812 06:18:43.383968 13696 leader_election.cc:290] T 00000000000000000000000000000000 P d8debbb357b8433fa1583798fb7c144a [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:43.384105 13700 raft_consensus.cc:2804] T 00000000000000000000000000000000 P d8debbb357b8433fa1583798fb7c144a [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:43.384402 13700 raft_consensus.cc:697] T 00000000000000000000000000000000 P d8debbb357b8433fa1583798fb7c144a [term 1 LEADER]: Becoming Leader. State: Replica: d8debbb357b8433fa1583798fb7c144a, State: Running, Role: LEADER
I20260812 06:18:43.384884 13700 consensus_queue.cc:237] T 00000000000000000000000000000000 P d8debbb357b8433fa1583798fb7c144a [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: "d8debbb357b8433fa1583798fb7c144a" member_type: VOTER }
I20260812 06:18:43.385052 13696 sys_catalog.cc:565] T 00000000000000000000000000000000 P d8debbb357b8433fa1583798fb7c144a [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:43.386700 13702 sys_catalog.cc:455] T 00000000000000000000000000000000 P d8debbb357b8433fa1583798fb7c144a [sys.catalog]: SysCatalogTable state changed. Reason: New leader d8debbb357b8433fa1583798fb7c144a. Latest consensus state: current_term: 1 leader_uuid: "d8debbb357b8433fa1583798fb7c144a" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d8debbb357b8433fa1583798fb7c144a" member_type: VOTER } }
I20260812 06:18:43.386818 13702 sys_catalog.cc:458] T 00000000000000000000000000000000 P d8debbb357b8433fa1583798fb7c144a [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:43.387161 13710 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:43.387154 13701 sys_catalog.cc:455] T 00000000000000000000000000000000 P d8debbb357b8433fa1583798fb7c144a [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "d8debbb357b8433fa1583798fb7c144a" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d8debbb357b8433fa1583798fb7c144a" member_type: VOTER } }
I20260812 06:18:43.387249 13701 sys_catalog.cc:458] T 00000000000000000000000000000000 P d8debbb357b8433fa1583798fb7c144a [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:43.389415 13710 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:43.389701 13591 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:43.394385 13710 catalog_manager.cc:1383] Generated new cluster ID: b99d0f480ade440c80711e7d7b726ffe
I20260812 06:18:43.394462 13710 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:43.428871 13710 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:43.430164 13710 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:43.440207 13710 catalog_manager.cc:6092] T 00000000000000000000000000000000 P d8debbb357b8433fa1583798fb7c144a: Generated new TSK 0
I20260812 06:18:43.441025 13710 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:43.454418 13591 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:43.457079 13723 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:18:43.457079 13728 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:18:43.457103 13724 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:18:43.457495 13591 server_base.cc:1061] running on GCE node
I20260812 06:18:43.457675 13591 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:43.457733 13591 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:18:43.457760 13591 hybrid_clock.cc:648] HybridClock initialized: now 1786515523457759 us; error 0 us; skew 500 ppm
I20260812 06:18:43.458735 13591 webserver.cc:533] Webserver started at http://127.13.69.193:36391/ using document root <none> and password file <none>
I20260812 06:18:43.458926 13591 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:43.459002 13591 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:43.459081 13591 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:43.459470 13591 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523306816-13591-0/minicluster-data/ts-0-root/instance:
uuid: "8b03c0e5b4f64db8b7c53a3cf64ef488"
format_stamp: "Formatted at 2026-08-12 06:18:43 on dist-test-slave-x5fp"
I20260812 06:18:43.461059 13591 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:43.462071 13734 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:18:43.462325 13591 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:43.462399 13591 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523306816-13591-0/minicluster-data/ts-0-root
uuid: "8b03c0e5b4f64db8b7c53a3cf64ef488"
format_stamp: "Formatted at 2026-08-12 06:18:43 on dist-test-slave-x5fp"
I20260812 06:18:43.462483 13591 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523306816-13591-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523306816-13591-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523306816-13591-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:18:43.484696 13591 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:43.485292 13591 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:43.485880 13591 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:43.486945 13591 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:43.487006 13591 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:43.487106 13591 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:43.487149 13591 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:43.494536 13591 rpc_server.cc:307] RPC server started. Bound to: 127.13.69.193:36403
I20260812 06:18:43.494596 13829 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.13.69.193:36403 every 8 connection(s)
I20260812 06:18:43.505017 13830 heartbeater.cc:344] Connected to a master server at 127.13.69.254:37785
I20260812 06:18:43.505297 13830 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:43.505797 13830 heartbeater.cc:507] Master 127.13.69.254:37785 requested a full tablet report, sending...
I20260812 06:18:43.507344 13638 ts_manager.cc:194] Registered new tserver with Master: 8b03c0e5b4f64db8b7c53a3cf64ef488 (127.13.69.193:36403)
I20260812 06:18:43.507891 13591 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012638729s
I20260812 06:18:43.508972 13638 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:41864
I20260812 06:18:43.518090 13638 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:41870:
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:18:43.532090 13777 tablet_service.cc:1511] Processing CreateTablet for tablet ba69f06a23b041838e77d4b0a9308312 (DEFAULT_TABLE table=heavy-update-compaction-test [id=89d9f5682b3944fe9d277e45ee21775a]), partition=
I20260812 06:18:43.532585 13777 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet ba69f06a23b041838e77d4b0a9308312. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:43.534983 13849 tablet_bootstrap.cc:492] T ba69f06a23b041838e77d4b0a9308312 P 8b03c0e5b4f64db8b7c53a3cf64ef488: Bootstrap starting.
I20260812 06:18:43.536386 13849 tablet_bootstrap.cc:654] T ba69f06a23b041838e77d4b0a9308312 P 8b03c0e5b4f64db8b7c53a3cf64ef488: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:43.537670 13849 tablet_bootstrap.cc:492] T ba69f06a23b041838e77d4b0a9308312 P 8b03c0e5b4f64db8b7c53a3cf64ef488: No bootstrap required, opened a new log
I20260812 06:18:43.537796 13849 ts_tablet_manager.cc:1403] T ba69f06a23b041838e77d4b0a9308312 P 8b03c0e5b4f64db8b7c53a3cf64ef488: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:18:43.538270 13849 raft_consensus.cc:359] T ba69f06a23b041838e77d4b0a9308312 P 8b03c0e5b4f64db8b7c53a3cf64ef488 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8b03c0e5b4f64db8b7c53a3cf64ef488" member_type: VOTER last_known_addr { host: "127.13.69.193" port: 36403 } }
I20260812 06:18:43.538403 13849 raft_consensus.cc:385] T ba69f06a23b041838e77d4b0a9308312 P 8b03c0e5b4f64db8b7c53a3cf64ef488 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:43.538453 13849 raft_consensus.cc:740] T ba69f06a23b041838e77d4b0a9308312 P 8b03c0e5b4f64db8b7c53a3cf64ef488 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 8b03c0e5b4f64db8b7c53a3cf64ef488, State: Initialized, Role: FOLLOWER
I20260812 06:18:43.538594 13849 consensus_queue.cc:260] T ba69f06a23b041838e77d4b0a9308312 P 8b03c0e5b4f64db8b7c53a3cf64ef488 [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: "8b03c0e5b4f64db8b7c53a3cf64ef488" member_type: VOTER last_known_addr { host: "127.13.69.193" port: 36403 } }
I20260812 06:18:43.538692 13849 raft_consensus.cc:399] T ba69f06a23b041838e77d4b0a9308312 P 8b03c0e5b4f64db8b7c53a3cf64ef488 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:43.538743 13849 raft_consensus.cc:493] T ba69f06a23b041838e77d4b0a9308312 P 8b03c0e5b4f64db8b7c53a3cf64ef488 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:43.538796 13849 raft_consensus.cc:3060] T ba69f06a23b041838e77d4b0a9308312 P 8b03c0e5b4f64db8b7c53a3cf64ef488 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:43.539549 13849 raft_consensus.cc:515] T ba69f06a23b041838e77d4b0a9308312 P 8b03c0e5b4f64db8b7c53a3cf64ef488 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8b03c0e5b4f64db8b7c53a3cf64ef488" member_type: VOTER last_known_addr { host: "127.13.69.193" port: 36403 } }
I20260812 06:18:43.539714 13849 leader_election.cc:304] T ba69f06a23b041838e77d4b0a9308312 P 8b03c0e5b4f64db8b7c53a3cf64ef488 [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: 8b03c0e5b4f64db8b7c53a3cf64ef488; no voters: 
I20260812 06:18:43.539965 13849 leader_election.cc:290] T ba69f06a23b041838e77d4b0a9308312 P 8b03c0e5b4f64db8b7c53a3cf64ef488 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:43.540102 13853 raft_consensus.cc:2804] T ba69f06a23b041838e77d4b0a9308312 P 8b03c0e5b4f64db8b7c53a3cf64ef488 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:43.540393 13849 ts_tablet_manager.cc:1434] T ba69f06a23b041838e77d4b0a9308312 P 8b03c0e5b4f64db8b7c53a3cf64ef488: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:43.540758 13853 raft_consensus.cc:697] T ba69f06a23b041838e77d4b0a9308312 P 8b03c0e5b4f64db8b7c53a3cf64ef488 [term 1 LEADER]: Becoming Leader. State: Replica: 8b03c0e5b4f64db8b7c53a3cf64ef488, State: Running, Role: LEADER
I20260812 06:18:43.540904 13830 heartbeater.cc:499] Master 127.13.69.254:37785 was elected leader, sending a full tablet report...
I20260812 06:18:43.540992 13853 consensus_queue.cc:237] T ba69f06a23b041838e77d4b0a9308312 P 8b03c0e5b4f64db8b7c53a3cf64ef488 [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: "8b03c0e5b4f64db8b7c53a3cf64ef488" member_type: VOTER last_known_addr { host: "127.13.69.193" port: 36403 } }
I20260812 06:18:43.543998 13638 catalog_manager.cc:5719] T ba69f06a23b041838e77d4b0a9308312 P 8b03c0e5b4f64db8b7c53a3cf64ef488 reported cstate change: term changed from 0 to 1, leader changed from <none> to 8b03c0e5b4f64db8b7c53a3cf64ef488 (127.13.69.193). New cstate: current_term: 1 leader_uuid: "8b03c0e5b4f64db8b7c53a3cf64ef488" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8b03c0e5b4f64db8b7c53a3cf64ef488" member_type: VOTER last_known_addr { host: "127.13.69.193" port: 36403 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:43.605558 13591 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.052s	user 0.014s	sys 0.009s
I20260812 06:18:43.745739 13832 maintenance_manager.cc:419] P 8b03c0e5b4f64db8b7c53a3cf64ef488: Scheduling FlushMRSOp(ba69f06a23b041838e77d4b0a9308312): perf score=19.054940
I20260812 06:18:43.911679 13743 maintenance_manager.cc:643] P 8b03c0e5b4f64db8b7c53a3cf64ef488: FlushMRSOp(ba69f06a23b041838e77d4b0a9308312) complete. Timing: real 0.166s	user 0.129s	sys 0.031s Metrics: {"bytes_written":12307491,"cfile_init":1,"compiler_manager_pool.queue_time_us":352,"delete_count":0,"dirs.queue_time_us":79,"dirs.run_cpu_time_us":204,"dirs.run_wall_time_us":1115,"drs_written":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4,"lbm_write_time_us":40366,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":168,"threads_started":1,"update_count":1500}
I20260812 06:18:43.913172 13832 maintenance_manager.cc:419] P 8b03c0e5b4f64db8b7c53a3cf64ef488: Scheduling LogGCOp(ba69f06a23b041838e77d4b0a9308312): free 20743880 bytes of WAL
I20260812 06:18:43.913515 13743 log_reader.cc:385] T ba69f06a23b041838e77d4b0a9308312: removed 2 log segments from log reader
I20260812 06:18:43.913583 13743 log.cc:1079] T ba69f06a23b041838e77d4b0a9308312 P 8b03c0e5b4f64db8b7c53a3cf64ef488: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/ba69f06a23b041838e77d4b0a9308312/wal-000000001 (ops 1-6)
I20260812 06:18:43.913647 13743 log.cc:1079] T ba69f06a23b041838e77d4b0a9308312 P 8b03c0e5b4f64db8b7c53a3cf64ef488: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/ba69f06a23b041838e77d4b0a9308312/wal-000000002 (ops 7-11)
I20260812 06:18:43.919679 13743 maintenance_manager.cc:643] P 8b03c0e5b4f64db8b7c53a3cf64ef488: LogGCOp(ba69f06a23b041838e77d4b0a9308312) complete. Timing: real 0.006s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:18:43.920142 13832 maintenance_manager.cc:419] P 8b03c0e5b4f64db8b7c53a3cf64ef488: Scheduling FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312): perf score=2.188937
I20260812 06:18:43.939441 13743 maintenance_manager.cc:643] P 8b03c0e5b4f64db8b7c53a3cf64ef488: FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312) complete. Timing: real 0.019s	user 0.018s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7299,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.940019 13832 maintenance_manager.cc:419] P 8b03c0e5b4f64db8b7c53a3cf64ef488: Scheduling MajorDeltaCompactionOp(ba69f06a23b041838e77d4b0a9308312): perf score=1.000000
I20260812 06:18:44.093807 13743 maintenance_manager.cc:643] P 8b03c0e5b4f64db8b7c53a3cf64ef488: MajorDeltaCompactionOp(ba69f06a23b041838e77d4b0a9308312) complete. Timing: real 0.154s	user 0.106s	sys 0.042s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":531,"lbm_read_time_us":11603,"lbm_reads_1-10_ms":1,"lbm_reads_lt_1ms":463,"lbm_write_time_us":22956,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11776,"thread_start_us":325,"threads_started":5,"update_count":2000}
I20260812 06:18:44.094430 13832 maintenance_manager.cc:419] P 8b03c0e5b4f64db8b7c53a3cf64ef488: Scheduling FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312): perf score=10.126437
I20260812 06:18:44.136051 13743 maintenance_manager.cc:643] P 8b03c0e5b4f64db8b7c53a3cf64ef488: FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312) complete. Timing: real 0.041s	user 0.030s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18083,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:44.136543 13832 maintenance_manager.cc:419] P 8b03c0e5b4f64db8b7c53a3cf64ef488: Scheduling UndoDeltaBlockGCOp(ba69f06a23b041838e77d4b0a9308312): 16411392 bytes on disk
I20260812 06:18:44.137024 13743 maintenance_manager.cc:643] P 8b03c0e5b4f64db8b7c53a3cf64ef488: UndoDeltaBlockGCOp(ba69f06a23b041838e77d4b0a9308312) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":44,"lbm_reads_lt_1ms":4}
I20260812 06:18:44.137457 13832 maintenance_manager.cc:419] P 8b03c0e5b4f64db8b7c53a3cf64ef488: Scheduling FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312): perf score=2.188937
I20260812 06:18:44.148504 13743 maintenance_manager.cc:643] P 8b03c0e5b4f64db8b7c53a3cf64ef488: FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312) complete. Timing: real 0.011s	user 0.005s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4079,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.148968 13832 maintenance_manager.cc:419] P 8b03c0e5b4f64db8b7c53a3cf64ef488: Scheduling MajorDeltaCompactionOp(ba69f06a23b041838e77d4b0a9308312): perf score=1.000000
I20260812 06:18:44.282099 13743 maintenance_manager.cc:643] P 8b03c0e5b4f64db8b7c53a3cf64ef488: MajorDeltaCompactionOp(ba69f06a23b041838e77d4b0a9308312) complete. Timing: real 0.133s	user 0.096s	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":129,"lbm_read_time_us":9246,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27978,"lbm_writes_lt_1ms":443,"mutex_wait_us":4,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7680,"update_count":2000}
I20260812 06:18:44.282904 13832 maintenance_manager.cc:419] P 8b03c0e5b4f64db8b7c53a3cf64ef488: Scheduling FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312): perf score=10.126437
I20260812 06:18:44.318249 13743 maintenance_manager.cc:643] P 8b03c0e5b4f64db8b7c53a3cf64ef488: FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312) complete. Timing: real 0.035s	user 0.018s	sys 0.016s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15453,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:44.318758 13832 maintenance_manager.cc:419] P 8b03c0e5b4f64db8b7c53a3cf64ef488: Scheduling FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312): perf score=2.188937
I20260812 06:18:44.335577 13743 maintenance_manager.cc:643] P 8b03c0e5b4f64db8b7c53a3cf64ef488: FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312) complete. Timing: real 0.017s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6304,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.336108 13832 maintenance_manager.cc:419] P 8b03c0e5b4f64db8b7c53a3cf64ef488: Scheduling MajorDeltaCompactionOp(ba69f06a23b041838e77d4b0a9308312): perf score=1.000000
I20260812 06:18:44.462623 13743 maintenance_manager.cc:643] P 8b03c0e5b4f64db8b7c53a3cf64ef488: MajorDeltaCompactionOp(ba69f06a23b041838e77d4b0a9308312) complete. Timing: real 0.126s	user 0.102s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":321,"lbm_read_time_us":8212,"lbm_reads_lt_1ms":468,"lbm_write_time_us":26234,"lbm_writes_lt_1ms":443,"mutex_wait_us":26,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":87680,"update_count":2000}
I20260812 06:18:44.463234 13832 maintenance_manager.cc:419] P 8b03c0e5b4f64db8b7c53a3cf64ef488: Scheduling FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312): perf score=10.126437
I20260812 06:18:44.517768 13743 maintenance_manager.cc:643] P 8b03c0e5b4f64db8b7c53a3cf64ef488: FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312) complete. Timing: real 0.054s	user 0.030s	sys 0.015s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16707,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:44.518256 13832 maintenance_manager.cc:419] P 8b03c0e5b4f64db8b7c53a3cf64ef488: Scheduling FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312): perf score=2.188937
I20260812 06:18:44.529179 13743 maintenance_manager.cc:643] P 8b03c0e5b4f64db8b7c53a3cf64ef488: FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4187,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.529639 13832 maintenance_manager.cc:419] P 8b03c0e5b4f64db8b7c53a3cf64ef488: Scheduling MajorDeltaCompactionOp(ba69f06a23b041838e77d4b0a9308312): perf score=1.000000
I20260812 06:18:44.677459 13743 maintenance_manager.cc:643] P 8b03c0e5b4f64db8b7c53a3cf64ef488: MajorDeltaCompactionOp(ba69f06a23b041838e77d4b0a9308312) complete. Timing: real 0.148s	user 0.109s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":976,"lbm_read_time_us":11105,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24557,"lbm_writes_lt_1ms":443,"mutex_wait_us":299,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8960,"update_count":2000}
I20260812 06:18:44.678006 13832 maintenance_manager.cc:419] P 8b03c0e5b4f64db8b7c53a3cf64ef488: Scheduling FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312): perf score=10.126437
I20260812 06:18:44.716905 13743 maintenance_manager.cc:643] P 8b03c0e5b4f64db8b7c53a3cf64ef488: FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312) complete. Timing: real 0.039s	user 0.025s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16305,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:44.717356 13832 maintenance_manager.cc:419] P 8b03c0e5b4f64db8b7c53a3cf64ef488: Scheduling MajorDeltaCompactionOp(ba69f06a23b041838e77d4b0a9308312): perf score=1.000000
I20260812 06:18:44.825481 13743 maintenance_manager.cc:643] P 8b03c0e5b4f64db8b7c53a3cf64ef488: MajorDeltaCompactionOp(ba69f06a23b041838e77d4b0a9308312) complete. Timing: real 0.108s	user 0.091s	sys 0.016s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569746,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":358,"lbm_read_time_us":7218,"lbm_reads_lt_1ms":363,"lbm_write_time_us":19539,"lbm_writes_lt_1ms":343,"mutex_wait_us":67,"peak_mem_usage":38262756,"reinsert_count":0,"update_count":1500}
I20260812 06:18:44.825992 13832 maintenance_manager.cc:419] P 8b03c0e5b4f64db8b7c53a3cf64ef488: Scheduling FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312): perf score=10.126437
I20260812 06:18:44.872659 13743 maintenance_manager.cc:643] P 8b03c0e5b4f64db8b7c53a3cf64ef488: FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312) complete. Timing: real 0.047s	user 0.013s	sys 0.020s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15959,"lbm_writes_lt_1ms":303,"mutex_wait_us":21,"reinsert_count":0,"update_count":1500}
I20260812 06:18:44.873190 13832 maintenance_manager.cc:419] P 8b03c0e5b4f64db8b7c53a3cf64ef488: Scheduling FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312): perf score=2.188937
I20260812 06:18:44.884516 13743 maintenance_manager.cc:643] P 8b03c0e5b4f64db8b7c53a3cf64ef488: FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4008,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.885113 13832 maintenance_manager.cc:419] P 8b03c0e5b4f64db8b7c53a3cf64ef488: Scheduling MajorDeltaCompactionOp(ba69f06a23b041838e77d4b0a9308312): perf score=1.000000
I20260812 06:18:45.030151 13743 maintenance_manager.cc:643] P 8b03c0e5b4f64db8b7c53a3cf64ef488: MajorDeltaCompactionOp(ba69f06a23b041838e77d4b0a9308312) complete. Timing: real 0.145s	user 0.113s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":295,"lbm_read_time_us":10221,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26819,"lbm_writes_lt_1ms":443,"mutex_wait_us":40,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:18:45.030720 13832 maintenance_manager.cc:419] P 8b03c0e5b4f64db8b7c53a3cf64ef488: Scheduling FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312): perf score=10.126437
I20260812 06:18:45.091420 13743 maintenance_manager.cc:643] P 8b03c0e5b4f64db8b7c53a3cf64ef488: FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312) complete. Timing: real 0.061s	user 0.022s	sys 0.021s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":15142,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:45.092033 13832 maintenance_manager.cc:419] P 8b03c0e5b4f64db8b7c53a3cf64ef488: Scheduling FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312): perf score=2.188937
I20260812 06:18:45.103792 13743 maintenance_manager.cc:643] P 8b03c0e5b4f64db8b7c53a3cf64ef488: FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4502,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.104300 13832 maintenance_manager.cc:419] P 8b03c0e5b4f64db8b7c53a3cf64ef488: Scheduling MajorDeltaCompactionOp(ba69f06a23b041838e77d4b0a9308312): perf score=1.000000
I20260812 06:18:45.265115 13743 maintenance_manager.cc:643] P 8b03c0e5b4f64db8b7c53a3cf64ef488: MajorDeltaCompactionOp(ba69f06a23b041838e77d4b0a9308312) complete. Timing: real 0.161s	user 0.116s	sys 0.044s 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":699,"lbm_read_time_us":12657,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28096,"lbm_writes_lt_1ms":443,"mutex_wait_us":48,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7424,"update_count":2000}
I20260812 06:18:45.265698 13832 maintenance_manager.cc:419] P 8b03c0e5b4f64db8b7c53a3cf64ef488: Scheduling FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312): perf score=10.126437
I20260812 06:18:45.309943 13743 maintenance_manager.cc:643] P 8b03c0e5b4f64db8b7c53a3cf64ef488: FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312) complete. Timing: real 0.044s	user 0.020s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14698,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:45.310477 13832 maintenance_manager.cc:419] P 8b03c0e5b4f64db8b7c53a3cf64ef488: Scheduling FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312): perf score=2.188937
I20260812 06:18:45.324141 13743 maintenance_manager.cc:643] P 8b03c0e5b4f64db8b7c53a3cf64ef488: FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312) complete. Timing: real 0.013s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5588,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.324630 13832 maintenance_manager.cc:419] P 8b03c0e5b4f64db8b7c53a3cf64ef488: Scheduling FlushMRSOp(ba69f06a23b041838e77d4b0a9308312): perf score=1.000000
I20260812 06:18:45.354678 13743 maintenance_manager.cc:643] P 8b03c0e5b4f64db8b7c53a3cf64ef488: FlushMRSOp(ba69f06a23b041838e77d4b0a9308312) complete. Timing: real 0.030s	user 0.022s	sys 0.005s Metrics: {"bytes_written":1275443,"cfile_init":1,"dirs.queue_time_us":65,"dirs.run_cpu_time_us":253,"dirs.run_wall_time_us":1360,"drs_written":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1539,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:45.355517 13832 maintenance_manager.cc:419] P 8b03c0e5b4f64db8b7c53a3cf64ef488: Scheduling LogGCOp(ba69f06a23b041838e77d4b0a9308312): free 121006433 bytes of WAL
I20260812 06:18:45.355787 13743 log_reader.cc:385] T ba69f06a23b041838e77d4b0a9308312: removed 12 log segments from log reader
I20260812 06:18:45.355865 13743 log.cc:1079] T ba69f06a23b041838e77d4b0a9308312 P 8b03c0e5b4f64db8b7c53a3cf64ef488: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/ba69f06a23b041838e77d4b0a9308312/wal-000000003 (ops 12-16)
I20260812 06:18:45.355916 13743 log.cc:1079] T ba69f06a23b041838e77d4b0a9308312 P 8b03c0e5b4f64db8b7c53a3cf64ef488: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/ba69f06a23b041838e77d4b0a9308312/wal-000000004 (ops 17-21)
I20260812 06:18:45.355976 13743 log.cc:1079] T ba69f06a23b041838e77d4b0a9308312 P 8b03c0e5b4f64db8b7c53a3cf64ef488: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/ba69f06a23b041838e77d4b0a9308312/wal-000000005 (ops 22-26)
I20260812 06:18:45.356020 13743 log.cc:1079] T ba69f06a23b041838e77d4b0a9308312 P 8b03c0e5b4f64db8b7c53a3cf64ef488: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/ba69f06a23b041838e77d4b0a9308312/wal-000000006 (ops 27-31)
I20260812 06:18:45.356060 13743 log.cc:1079] T ba69f06a23b041838e77d4b0a9308312 P 8b03c0e5b4f64db8b7c53a3cf64ef488: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/ba69f06a23b041838e77d4b0a9308312/wal-000000007 (ops 32-36)
I20260812 06:18:45.356098 13743 log.cc:1079] T ba69f06a23b041838e77d4b0a9308312 P 8b03c0e5b4f64db8b7c53a3cf64ef488: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/ba69f06a23b041838e77d4b0a9308312/wal-000000008 (ops 37-40)
I20260812 06:18:45.356137 13743 log.cc:1079] T ba69f06a23b041838e77d4b0a9308312 P 8b03c0e5b4f64db8b7c53a3cf64ef488: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/ba69f06a23b041838e77d4b0a9308312/wal-000000009 (ops 41-45)
I20260812 06:18:45.356175 13743 log.cc:1079] T ba69f06a23b041838e77d4b0a9308312 P 8b03c0e5b4f64db8b7c53a3cf64ef488: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/ba69f06a23b041838e77d4b0a9308312/wal-000000010 (ops 46-50)
I20260812 06:18:45.356220 13743 log.cc:1079] T ba69f06a23b041838e77d4b0a9308312 P 8b03c0e5b4f64db8b7c53a3cf64ef488: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/ba69f06a23b041838e77d4b0a9308312/wal-000000011 (ops 51-55)
I20260812 06:18:45.356261 13743 log.cc:1079] T ba69f06a23b041838e77d4b0a9308312 P 8b03c0e5b4f64db8b7c53a3cf64ef488: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/ba69f06a23b041838e77d4b0a9308312/wal-000000012 (ops 56-60)
I20260812 06:18:45.356299 13743 log.cc:1079] T ba69f06a23b041838e77d4b0a9308312 P 8b03c0e5b4f64db8b7c53a3cf64ef488: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/ba69f06a23b041838e77d4b0a9308312/wal-000000013 (ops 61-65)
I20260812 06:18:45.356338 13743 log.cc:1079] T ba69f06a23b041838e77d4b0a9308312 P 8b03c0e5b4f64db8b7c53a3cf64ef488: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/ba69f06a23b041838e77d4b0a9308312/wal-000000014 (ops 66-70)
I20260812 06:18:45.383373 13743 maintenance_manager.cc:643] P 8b03c0e5b4f64db8b7c53a3cf64ef488: LogGCOp(ba69f06a23b041838e77d4b0a9308312) complete. Timing: real 0.028s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:18:45.383937 13832 maintenance_manager.cc:419] P 8b03c0e5b4f64db8b7c53a3cf64ef488: Scheduling UndoDeltaBlockGCOp(ba69f06a23b041838e77d4b0a9308312): 483 bytes on disk
I20260812 06:18:45.384471 13743 maintenance_manager.cc:643] P 8b03c0e5b4f64db8b7c53a3cf64ef488: UndoDeltaBlockGCOp(ba69f06a23b041838e77d4b0a9308312) 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:18:45.385084 13832 maintenance_manager.cc:419] P 8b03c0e5b4f64db8b7c53a3cf64ef488: Scheduling FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312): perf score=3.181125
I20260812 06:18:45.397245 13743 maintenance_manager.cc:643] P 8b03c0e5b4f64db8b7c53a3cf64ef488: FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312) complete. Timing: real 0.012s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4787,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:45.397678 13832 maintenance_manager.cc:419] P 8b03c0e5b4f64db8b7c53a3cf64ef488: Scheduling LogGCOp(ba69f06a23b041838e77d4b0a9308312): free 11564875 bytes of WAL
I20260812 06:18:45.397886 13743 log_reader.cc:385] T ba69f06a23b041838e77d4b0a9308312: removed 1 log segments from log reader
I20260812 06:18:45.397930 13743 log.cc:1079] T ba69f06a23b041838e77d4b0a9308312 P 8b03c0e5b4f64db8b7c53a3cf64ef488: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/ba69f06a23b041838e77d4b0a9308312/wal-000000015 (ops 71-74)
I20260812 06:18:45.400184 13743 maintenance_manager.cc:643] P 8b03c0e5b4f64db8b7c53a3cf64ef488: LogGCOp(ba69f06a23b041838e77d4b0a9308312) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:18:45.400488 13832 maintenance_manager.cc:419] P 8b03c0e5b4f64db8b7c53a3cf64ef488: Scheduling FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312): perf score=2.188937
I20260812 06:18:45.419143 13743 maintenance_manager.cc:643] P 8b03c0e5b4f64db8b7c53a3cf64ef488: FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312) complete. Timing: real 0.018s	user 0.006s	sys 0.009s 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:18:45.419849 13832 maintenance_manager.cc:419] P 8b03c0e5b4f64db8b7c53a3cf64ef488: Scheduling MajorDeltaCompactionOp(ba69f06a23b041838e77d4b0a9308312): perf score=1.000000
I20260812 06:18:45.613579 13743 maintenance_manager.cc:643] P 8b03c0e5b4f64db8b7c53a3cf64ef488: MajorDeltaCompactionOp(ba69f06a23b041838e77d4b0a9308312) complete. Timing: real 0.194s	user 0.148s	sys 0.044s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877329,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":417,"lbm_read_time_us":12697,"lbm_reads_lt_1ms":666,"lbm_write_time_us":34459,"lbm_writes_lt_1ms":643,"mutex_wait_us":359,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1408,"thread_start_us":295,"threads_started":1,"update_count":3000}
I20260812 06:18:45.614295 13832 maintenance_manager.cc:419] P 8b03c0e5b4f64db8b7c53a3cf64ef488: Scheduling FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312): perf score=14.095187
I20260812 06:18:45.672569 13743 maintenance_manager.cc:643] P 8b03c0e5b4f64db8b7c53a3cf64ef488: FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312) complete. Timing: real 0.058s	user 0.043s	sys 0.011s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":21186,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:45.673187 13832 maintenance_manager.cc:419] P 8b03c0e5b4f64db8b7c53a3cf64ef488: Scheduling FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312): perf score=2.188937
I20260812 06:18:45.690179 13743 maintenance_manager.cc:643] P 8b03c0e5b4f64db8b7c53a3cf64ef488: FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312) complete. Timing: real 0.017s	user 0.010s	sys 0.000s 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:18:45.690685 13832 maintenance_manager.cc:419] P 8b03c0e5b4f64db8b7c53a3cf64ef488: Scheduling MajorDeltaCompactionOp(ba69f06a23b041838e77d4b0a9308312): perf score=1.000000
I20260812 06:18:45.873499 13743 maintenance_manager.cc:643] P 8b03c0e5b4f64db8b7c53a3cf64ef488: MajorDeltaCompactionOp(ba69f06a23b041838e77d4b0a9308312) complete. Timing: real 0.183s	user 0.122s	sys 0.055s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774692,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":263,"lbm_read_time_us":12110,"lbm_reads_lt_1ms":564,"lbm_write_time_us":31841,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6528,"update_count":2500}
I20260812 06:18:45.874038 13832 maintenance_manager.cc:419] P 8b03c0e5b4f64db8b7c53a3cf64ef488: Scheduling FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312): perf score=14.095187
I20260812 06:18:45.927193 13743 maintenance_manager.cc:643] P 8b03c0e5b4f64db8b7c53a3cf64ef488: FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312) complete. Timing: real 0.053s	user 0.026s	sys 0.024s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23387,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:45.927697 13832 maintenance_manager.cc:419] P 8b03c0e5b4f64db8b7c53a3cf64ef488: Scheduling FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312): perf score=2.188937
I20260812 06:18:45.939146 13743 maintenance_manager.cc:643] P 8b03c0e5b4f64db8b7c53a3cf64ef488: FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4113,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.939641 13832 maintenance_manager.cc:419] P 8b03c0e5b4f64db8b7c53a3cf64ef488: Scheduling MajorDeltaCompactionOp(ba69f06a23b041838e77d4b0a9308312): perf score=1.000000
I20260812 06:18:46.124183 13743 maintenance_manager.cc:643] P 8b03c0e5b4f64db8b7c53a3cf64ef488: MajorDeltaCompactionOp(ba69f06a23b041838e77d4b0a9308312) complete. Timing: real 0.184s	user 0.116s	sys 0.048s 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":704,"lbm_read_time_us":10101,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29291,"lbm_writes_lt_1ms":543,"mutex_wait_us":34,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13696,"update_count":2500}
I20260812 06:18:46.125001 13832 maintenance_manager.cc:419] P 8b03c0e5b4f64db8b7c53a3cf64ef488: Scheduling FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312): perf score=14.095187
I20260812 06:18:46.172581 13743 maintenance_manager.cc:643] P 8b03c0e5b4f64db8b7c53a3cf64ef488: FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312) complete. Timing: real 0.047s	user 0.032s	sys 0.008s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":19376,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:46.173101 13832 maintenance_manager.cc:419] P 8b03c0e5b4f64db8b7c53a3cf64ef488: Scheduling FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312): perf score=2.188937
I20260812 06:18:46.183568 13743 maintenance_manager.cc:643] P 8b03c0e5b4f64db8b7c53a3cf64ef488: FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4088,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:46.183998 13832 maintenance_manager.cc:419] P 8b03c0e5b4f64db8b7c53a3cf64ef488: Scheduling MajorDeltaCompactionOp(ba69f06a23b041838e77d4b0a9308312): perf score=1.000000
I20260812 06:18:46.337802 13743 maintenance_manager.cc:643] P 8b03c0e5b4f64db8b7c53a3cf64ef488: MajorDeltaCompactionOp(ba69f06a23b041838e77d4b0a9308312) complete. Timing: real 0.154s	user 0.123s	sys 0.020s 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":365,"lbm_read_time_us":10740,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29206,"lbm_writes_lt_1ms":543,"mutex_wait_us":3,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2500}
I20260812 06:18:46.338420 13832 maintenance_manager.cc:419] P 8b03c0e5b4f64db8b7c53a3cf64ef488: Scheduling FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312): perf score=14.095187
I20260812 06:18:46.389510 13743 maintenance_manager.cc:643] P 8b03c0e5b4f64db8b7c53a3cf64ef488: FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312) complete. Timing: real 0.051s	user 0.029s	sys 0.012s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":18329,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:46.390136 13832 maintenance_manager.cc:419] P 8b03c0e5b4f64db8b7c53a3cf64ef488: Scheduling FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312): perf score=2.188937
I20260812 06:18:46.405719 13743 maintenance_manager.cc:643] P 8b03c0e5b4f64db8b7c53a3cf64ef488: FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312) complete. Timing: real 0.015s	user 0.005s	sys 0.010s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5914,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:46.406476 13832 maintenance_manager.cc:419] P 8b03c0e5b4f64db8b7c53a3cf64ef488: Scheduling MajorDeltaCompactionOp(ba69f06a23b041838e77d4b0a9308312): perf score=1.000000
I20260812 06:18:46.560869 13743 maintenance_manager.cc:643] P 8b03c0e5b4f64db8b7c53a3cf64ef488: MajorDeltaCompactionOp(ba69f06a23b041838e77d4b0a9308312) complete. Timing: real 0.154s	user 0.103s	sys 0.047s 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":130,"lbm_read_time_us":10029,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28429,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2500}
I20260812 06:18:46.561667 13832 maintenance_manager.cc:419] P 8b03c0e5b4f64db8b7c53a3cf64ef488: Scheduling FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312): perf score=11.118625
I20260812 06:18:46.598554 13743 maintenance_manager.cc:643] P 8b03c0e5b4f64db8b7c53a3cf64ef488: FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312) complete. Timing: real 0.037s	user 0.030s	sys 0.005s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15813,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:46.599303 13832 maintenance_manager.cc:419] P 8b03c0e5b4f64db8b7c53a3cf64ef488: Scheduling FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312): perf score=2.188937
I20260812 06:18:46.626559 13743 maintenance_manager.cc:643] P 8b03c0e5b4f64db8b7c53a3cf64ef488: FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312) complete. Timing: real 0.027s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5273,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:46.627018 13832 maintenance_manager.cc:419] P 8b03c0e5b4f64db8b7c53a3cf64ef488: Scheduling FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312): perf score=2.188937
I20260812 06:18:46.637462 13743 maintenance_manager.cc:643] P 8b03c0e5b4f64db8b7c53a3cf64ef488: FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312) complete. Timing: real 0.010s	user 0.004s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3918,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:46.637907 13832 maintenance_manager.cc:419] P 8b03c0e5b4f64db8b7c53a3cf64ef488: Scheduling MajorDeltaCompactionOp(ba69f06a23b041838e77d4b0a9308312): perf score=1.000000
I20260812 06:18:46.804605 13743 maintenance_manager.cc:643] P 8b03c0e5b4f64db8b7c53a3cf64ef488: MajorDeltaCompactionOp(ba69f06a23b041838e77d4b0a9308312) complete. Timing: real 0.167s	user 0.126s	sys 0.032s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1037,"lbm_read_time_us":11199,"lbm_reads_lt_1ms":573,"lbm_write_time_us":31913,"lbm_writes_lt_1ms":543,"mutex_wait_us":32,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":15488,"update_count":2500}
I20260812 06:18:46.805230 13832 maintenance_manager.cc:419] P 8b03c0e5b4f64db8b7c53a3cf64ef488: Scheduling FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312): perf score=14.095187
I20260812 06:18:46.851621 13743 maintenance_manager.cc:643] P 8b03c0e5b4f64db8b7c53a3cf64ef488: FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312) complete. Timing: real 0.046s	user 0.032s	sys 0.012s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":20667,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:46.852139 13832 maintenance_manager.cc:419] P 8b03c0e5b4f64db8b7c53a3cf64ef488: Scheduling FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312): perf score=2.188937
I20260812 06:18:46.862658 13743 maintenance_manager.cc:643] P 8b03c0e5b4f64db8b7c53a3cf64ef488: FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312) complete. Timing: real 0.010s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4042,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:46.863251 13832 maintenance_manager.cc:419] P 8b03c0e5b4f64db8b7c53a3cf64ef488: Scheduling FlushMRSOp(ba69f06a23b041838e77d4b0a9308312): perf score=1.000000
I20260812 06:18:46.898191 13743 maintenance_manager.cc:643] P 8b03c0e5b4f64db8b7c53a3cf64ef488: FlushMRSOp(ba69f06a23b041838e77d4b0a9308312) complete. Timing: real 0.035s	user 0.028s	sys 0.005s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":72,"dirs.run_cpu_time_us":339,"dirs.run_wall_time_us":1704,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1913,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:18:46.898976 13832 maintenance_manager.cc:419] P 8b03c0e5b4f64db8b7c53a3cf64ef488: Scheduling LogGCOp(ba69f06a23b041838e77d4b0a9308312): free 121006402 bytes of WAL
I20260812 06:18:46.899214 13743 log_reader.cc:385] T ba69f06a23b041838e77d4b0a9308312: removed 12 log segments from log reader
I20260812 06:18:46.899259 13743 log.cc:1079] T ba69f06a23b041838e77d4b0a9308312 P 8b03c0e5b4f64db8b7c53a3cf64ef488: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/ba69f06a23b041838e77d4b0a9308312/wal-000000016 (ops 75-79)
I20260812 06:18:46.899288 13743 log.cc:1079] T ba69f06a23b041838e77d4b0a9308312 P 8b03c0e5b4f64db8b7c53a3cf64ef488: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/ba69f06a23b041838e77d4b0a9308312/wal-000000017 (ops 80-84)
I20260812 06:18:46.899343 13743 log.cc:1079] T ba69f06a23b041838e77d4b0a9308312 P 8b03c0e5b4f64db8b7c53a3cf64ef488: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/ba69f06a23b041838e77d4b0a9308312/wal-000000018 (ops 85-88)
I20260812 06:18:46.899384 13743 log.cc:1079] T ba69f06a23b041838e77d4b0a9308312 P 8b03c0e5b4f64db8b7c53a3cf64ef488: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/ba69f06a23b041838e77d4b0a9308312/wal-000000019 (ops 89-93)
I20260812 06:18:46.899411 13743 log.cc:1079] T ba69f06a23b041838e77d4b0a9308312 P 8b03c0e5b4f64db8b7c53a3cf64ef488: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/ba69f06a23b041838e77d4b0a9308312/wal-000000020 (ops 94-98)
I20260812 06:18:46.899468 13743 log.cc:1079] T ba69f06a23b041838e77d4b0a9308312 P 8b03c0e5b4f64db8b7c53a3cf64ef488: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/ba69f06a23b041838e77d4b0a9308312/wal-000000021 (ops 99-103)
I20260812 06:18:46.899528 13743 log.cc:1079] T ba69f06a23b041838e77d4b0a9308312 P 8b03c0e5b4f64db8b7c53a3cf64ef488: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/ba69f06a23b041838e77d4b0a9308312/wal-000000022 (ops 104-108)
I20260812 06:18:46.899566 13743 log.cc:1079] T ba69f06a23b041838e77d4b0a9308312 P 8b03c0e5b4f64db8b7c53a3cf64ef488: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/ba69f06a23b041838e77d4b0a9308312/wal-000000023 (ops 109-113)
I20260812 06:18:46.899605 13743 log.cc:1079] T ba69f06a23b041838e77d4b0a9308312 P 8b03c0e5b4f64db8b7c53a3cf64ef488: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/ba69f06a23b041838e77d4b0a9308312/wal-000000024 (ops 114-118)
I20260812 06:18:46.899645 13743 log.cc:1079] T ba69f06a23b041838e77d4b0a9308312 P 8b03c0e5b4f64db8b7c53a3cf64ef488: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/ba69f06a23b041838e77d4b0a9308312/wal-000000025 (ops 119-123)
I20260812 06:18:46.899683 13743 log.cc:1079] T ba69f06a23b041838e77d4b0a9308312 P 8b03c0e5b4f64db8b7c53a3cf64ef488: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/ba69f06a23b041838e77d4b0a9308312/wal-000000026 (ops 124-128)
I20260812 06:18:46.899724 13743 log.cc:1079] T ba69f06a23b041838e77d4b0a9308312 P 8b03c0e5b4f64db8b7c53a3cf64ef488: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/ba69f06a23b041838e77d4b0a9308312/wal-000000027 (ops 129-133)
I20260812 06:18:46.928579 13743 maintenance_manager.cc:643] P 8b03c0e5b4f64db8b7c53a3cf64ef488: LogGCOp(ba69f06a23b041838e77d4b0a9308312) complete. Timing: real 0.029s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:18:46.929198 13832 maintenance_manager.cc:419] P 8b03c0e5b4f64db8b7c53a3cf64ef488: Scheduling FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312): perf score=3.181125
I20260812 06:18:46.943152 13743 maintenance_manager.cc:643] P 8b03c0e5b4f64db8b7c53a3cf64ef488: FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312) complete. Timing: real 0.014s	user 0.000s	sys 0.011s Metrics: {"bytes_written":4677001,"delete_count":0,"lbm_write_time_us":5391,"lbm_writes_lt_1ms":117,"reinsert_count":0,"update_count":570}
I20260812 06:18:46.943634 13832 maintenance_manager.cc:419] P 8b03c0e5b4f64db8b7c53a3cf64ef488: Scheduling LogGCOp(ba69f06a23b041838e77d4b0a9308312): free 12018006 bytes of WAL
I20260812 06:18:46.943881 13743 log_reader.cc:385] T ba69f06a23b041838e77d4b0a9308312: removed 1 log segments from log reader
I20260812 06:18:46.943940 13743 log.cc:1079] T ba69f06a23b041838e77d4b0a9308312 P 8b03c0e5b4f64db8b7c53a3cf64ef488: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/ba69f06a23b041838e77d4b0a9308312/wal-000000028 (ops 134-138)
I20260812 06:18:46.947017 13743 maintenance_manager.cc:643] P 8b03c0e5b4f64db8b7c53a3cf64ef488: LogGCOp(ba69f06a23b041838e77d4b0a9308312) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:18:46.947335 13832 maintenance_manager.cc:419] P 8b03c0e5b4f64db8b7c53a3cf64ef488: Scheduling UndoDeltaBlockGCOp(ba69f06a23b041838e77d4b0a9308312): 492 bytes on disk
I20260812 06:18:46.947806 13743 maintenance_manager.cc:643] P 8b03c0e5b4f64db8b7c53a3cf64ef488: UndoDeltaBlockGCOp(ba69f06a23b041838e77d4b0a9308312) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":68,"lbm_reads_lt_1ms":4}
I20260812 06:18:46.948294 13832 maintenance_manager.cc:419] P 8b03c0e5b4f64db8b7c53a3cf64ef488: Scheduling FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312): perf score=2.188937
I20260812 06:18:46.959503 13743 maintenance_manager.cc:643] P 8b03c0e5b4f64db8b7c53a3cf64ef488: FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3528305,"delete_count":0,"lbm_write_time_us":3915,"lbm_writes_lt_1ms":89,"reinsert_count":0,"update_count":430}
I20260812 06:18:46.959971 13832 maintenance_manager.cc:419] P 8b03c0e5b4f64db8b7c53a3cf64ef488: Scheduling MajorDeltaCompactionOp(ba69f06a23b041838e77d4b0a9308312): perf score=1.000000
I20260812 06:18:47.185050 13743 maintenance_manager.cc:643] P 8b03c0e5b4f64db8b7c53a3cf64ef488: MajorDeltaCompactionOp(ba69f06a23b041838e77d4b0a9308312) complete. Timing: real 0.225s	user 0.137s	sys 0.083s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979737,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":428,"lbm_read_time_us":15362,"lbm_reads_lt_1ms":770,"lbm_write_time_us":37420,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"thread_start_us":80,"threads_started":1,"update_count":3500}
I20260812 06:18:47.185899 13832 maintenance_manager.cc:419] P 8b03c0e5b4f64db8b7c53a3cf64ef488: Scheduling FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312): perf score=15.087375
I20260812 06:18:47.258916 13743 maintenance_manager.cc:643] P 8b03c0e5b4f64db8b7c53a3cf64ef488: FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312) complete. Timing: real 0.073s	user 0.032s	sys 0.027s Metrics: {"bytes_written":16820145,"delete_count":0,"lbm_write_time_us":24985,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":412,"reinsert_count":0,"update_count":2050}
I20260812 06:18:47.259546 13832 maintenance_manager.cc:419] P 8b03c0e5b4f64db8b7c53a3cf64ef488: Scheduling FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312): perf score=6.157687
I20260812 06:18:47.280059 13743 maintenance_manager.cc:643] P 8b03c0e5b4f64db8b7c53a3cf64ef488: FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312) complete. Timing: real 0.020s	user 0.014s	sys 0.003s Metrics: {"bytes_written":7794836,"delete_count":0,"lbm_write_time_us":8294,"lbm_writes_lt_1ms":193,"reinsert_count":0,"update_count":950}
I20260812 06:18:47.280567 13832 maintenance_manager.cc:419] P 8b03c0e5b4f64db8b7c53a3cf64ef488: Scheduling MajorDeltaCompactionOp(ba69f06a23b041838e77d4b0a9308312): perf score=1.000000
I20260812 06:18:47.499712 13743 maintenance_manager.cc:643] P 8b03c0e5b4f64db8b7c53a3cf64ef488: MajorDeltaCompactionOp(ba69f06a23b041838e77d4b0a9308312) complete. Timing: real 0.219s	user 0.150s	sys 0.062s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877103,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":236,"lbm_read_time_us":14593,"lbm_reads_lt_1ms":672,"lbm_write_time_us":36660,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:18:47.500313 13832 maintenance_manager.cc:419] P 8b03c0e5b4f64db8b7c53a3cf64ef488: Scheduling FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312): perf score=18.063937
I20260812 06:18:47.578022 13743 maintenance_manager.cc:643] P 8b03c0e5b4f64db8b7c53a3cf64ef488: FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312) complete. Timing: real 0.077s	user 0.034s	sys 0.039s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":31785,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:47.578557 13832 maintenance_manager.cc:419] P 8b03c0e5b4f64db8b7c53a3cf64ef488: Scheduling FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312): perf score=2.188937
I20260812 06:18:47.595374 13743 maintenance_manager.cc:643] P 8b03c0e5b4f64db8b7c53a3cf64ef488: FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312) complete. Timing: real 0.017s	user 0.009s	sys 0.004s 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:18:47.596120 13832 maintenance_manager.cc:419] P 8b03c0e5b4f64db8b7c53a3cf64ef488: Scheduling MajorDeltaCompactionOp(ba69f06a23b041838e77d4b0a9308312): perf score=1.000000
I20260812 06:18:47.803224 13743 maintenance_manager.cc:643] P 8b03c0e5b4f64db8b7c53a3cf64ef488: MajorDeltaCompactionOp(ba69f06a23b041838e77d4b0a9308312) complete. Timing: real 0.207s	user 0.139s	sys 0.067s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877102,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":258,"lbm_read_time_us":15763,"lbm_reads_lt_1ms":672,"lbm_write_time_us":37359,"lbm_writes_lt_1ms":643,"mutex_wait_us":49,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":61568,"update_count":3000}
I20260812 06:18:47.804024 13832 maintenance_manager.cc:419] P 8b03c0e5b4f64db8b7c53a3cf64ef488: Scheduling FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312): perf score=14.095187
I20260812 06:18:47.864501 13743 maintenance_manager.cc:643] P 8b03c0e5b4f64db8b7c53a3cf64ef488: FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312) complete. Timing: real 0.060s	user 0.023s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23259,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:47.865046 13832 maintenance_manager.cc:419] P 8b03c0e5b4f64db8b7c53a3cf64ef488: Scheduling FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312): perf score=2.188937
I20260812 06:18:47.876681 13743 maintenance_manager.cc:643] P 8b03c0e5b4f64db8b7c53a3cf64ef488: FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4291,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:47.877341 13832 maintenance_manager.cc:419] P 8b03c0e5b4f64db8b7c53a3cf64ef488: Scheduling MajorDeltaCompactionOp(ba69f06a23b041838e77d4b0a9308312): perf score=1.000000
I20260812 06:18:48.063784 13743 maintenance_manager.cc:643] P 8b03c0e5b4f64db8b7c53a3cf64ef488: MajorDeltaCompactionOp(ba69f06a23b041838e77d4b0a9308312) complete. Timing: real 0.186s	user 0.110s	sys 0.065s 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":1781,"lbm_read_time_us":12930,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32177,"lbm_writes_lt_1ms":543,"mutex_wait_us":630,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2500}
I20260812 06:18:48.064543 13832 maintenance_manager.cc:419] P 8b03c0e5b4f64db8b7c53a3cf64ef488: Scheduling FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312): perf score=14.095187
I20260812 06:18:48.128780 13743 maintenance_manager.cc:643] P 8b03c0e5b4f64db8b7c53a3cf64ef488: FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312) complete. Timing: real 0.064s	user 0.029s	sys 0.031s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":26218,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":400,"reinsert_count":0,"update_count":2000}
I20260812 06:18:48.129375 13832 maintenance_manager.cc:419] P 8b03c0e5b4f64db8b7c53a3cf64ef488: Scheduling FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312): perf score=2.188937
I20260812 06:18:48.143419 13743 maintenance_manager.cc:643] P 8b03c0e5b4f64db8b7c53a3cf64ef488: FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312) complete. Timing: real 0.014s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5279,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:48.144233 13832 maintenance_manager.cc:419] P 8b03c0e5b4f64db8b7c53a3cf64ef488: Scheduling MajorDeltaCompactionOp(ba69f06a23b041838e77d4b0a9308312): perf score=1.000000
I20260812 06:18:48.320410 13743 maintenance_manager.cc:643] P 8b03c0e5b4f64db8b7c53a3cf64ef488: MajorDeltaCompactionOp(ba69f06a23b041838e77d4b0a9308312) complete. Timing: real 0.176s	user 0.128s	sys 0.048s 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":660,"lbm_read_time_us":13350,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31360,"lbm_writes_lt_1ms":543,"mutex_wait_us":294,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4864,"update_count":2500}
I20260812 06:18:48.321122 13832 maintenance_manager.cc:419] P 8b03c0e5b4f64db8b7c53a3cf64ef488: Scheduling FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312): perf score=14.095187
I20260812 06:18:48.383778 13743 maintenance_manager.cc:643] P 8b03c0e5b4f64db8b7c53a3cf64ef488: FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312) complete. Timing: real 0.062s	user 0.003s	sys 0.056s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23552,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:48.384341 13832 maintenance_manager.cc:419] P 8b03c0e5b4f64db8b7c53a3cf64ef488: Scheduling FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312): perf score=2.188937
I20260812 06:18:48.395367 13743 maintenance_manager.cc:643] P 8b03c0e5b4f64db8b7c53a3cf64ef488: FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4259,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:48.396054 13832 maintenance_manager.cc:419] P 8b03c0e5b4f64db8b7c53a3cf64ef488: Scheduling FlushMRSOp(ba69f06a23b041838e77d4b0a9308312): perf score=1.000000
I20260812 06:18:48.438244 13743 maintenance_manager.cc:643] P 8b03c0e5b4f64db8b7c53a3cf64ef488: FlushMRSOp(ba69f06a23b041838e77d4b0a9308312) complete. Timing: real 0.042s	user 0.027s	sys 0.003s Metrics: {"bytes_written":1193507,"cfile_init":1,"dirs.queue_time_us":72,"dirs.run_cpu_time_us":388,"dirs.run_wall_time_us":3200,"drs_written":1,"lbm_read_time_us":77,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1712,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:48.438992 13832 maintenance_manager.cc:419] P 8b03c0e5b4f64db8b7c53a3cf64ef488: Scheduling LogGCOp(ba69f06a23b041838e77d4b0a9308312): free 112239560 bytes of WAL
I20260812 06:18:48.439250 13743 log_reader.cc:385] T ba69f06a23b041838e77d4b0a9308312: removed 11 log segments from log reader
I20260812 06:18:48.439303 13743 log.cc:1079] T ba69f06a23b041838e77d4b0a9308312 P 8b03c0e5b4f64db8b7c53a3cf64ef488: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/ba69f06a23b041838e77d4b0a9308312/wal-000000029 (ops 139-143)
I20260812 06:18:48.439363 13743 log.cc:1079] T ba69f06a23b041838e77d4b0a9308312 P 8b03c0e5b4f64db8b7c53a3cf64ef488: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/ba69f06a23b041838e77d4b0a9308312/wal-000000030 (ops 144-148)
I20260812 06:18:48.439419 13743 log.cc:1079] T ba69f06a23b041838e77d4b0a9308312 P 8b03c0e5b4f64db8b7c53a3cf64ef488: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/ba69f06a23b041838e77d4b0a9308312/wal-000000031 (ops 149-153)
I20260812 06:18:48.439478 13743 log.cc:1079] T ba69f06a23b041838e77d4b0a9308312 P 8b03c0e5b4f64db8b7c53a3cf64ef488: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/ba69f06a23b041838e77d4b0a9308312/wal-000000032 (ops 154-158)
I20260812 06:18:48.439530 13743 log.cc:1079] T ba69f06a23b041838e77d4b0a9308312 P 8b03c0e5b4f64db8b7c53a3cf64ef488: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/ba69f06a23b041838e77d4b0a9308312/wal-000000033 (ops 159-162)
I20260812 06:18:48.439592 13743 log.cc:1079] T ba69f06a23b041838e77d4b0a9308312 P 8b03c0e5b4f64db8b7c53a3cf64ef488: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/ba69f06a23b041838e77d4b0a9308312/wal-000000034 (ops 163-167)
I20260812 06:18:48.439638 13743 log.cc:1079] T ba69f06a23b041838e77d4b0a9308312 P 8b03c0e5b4f64db8b7c53a3cf64ef488: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/ba69f06a23b041838e77d4b0a9308312/wal-000000035 (ops 168-172)
I20260812 06:18:48.439683 13743 log.cc:1079] T ba69f06a23b041838e77d4b0a9308312 P 8b03c0e5b4f64db8b7c53a3cf64ef488: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/ba69f06a23b041838e77d4b0a9308312/wal-000000036 (ops 173-177)
I20260812 06:18:48.439726 13743 log.cc:1079] T ba69f06a23b041838e77d4b0a9308312 P 8b03c0e5b4f64db8b7c53a3cf64ef488: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/ba69f06a23b041838e77d4b0a9308312/wal-000000037 (ops 178-182)
I20260812 06:18:48.439772 13743 log.cc:1079] T ba69f06a23b041838e77d4b0a9308312 P 8b03c0e5b4f64db8b7c53a3cf64ef488: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/ba69f06a23b041838e77d4b0a9308312/wal-000000038 (ops 183-187)
I20260812 06:18:48.439817 13743 log.cc:1079] T ba69f06a23b041838e77d4b0a9308312 P 8b03c0e5b4f64db8b7c53a3cf64ef488: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/ba69f06a23b041838e77d4b0a9308312/wal-000000039 (ops 188-192)
I20260812 06:18:48.465303 13743 maintenance_manager.cc:643] P 8b03c0e5b4f64db8b7c53a3cf64ef488: LogGCOp(ba69f06a23b041838e77d4b0a9308312) complete. Timing: real 0.026s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:18:48.465876 13832 maintenance_manager.cc:419] P 8b03c0e5b4f64db8b7c53a3cf64ef488: Scheduling UndoDeltaBlockGCOp(ba69f06a23b041838e77d4b0a9308312): 463 bytes on disk
I20260812 06:18:48.466653 13743 maintenance_manager.cc:643] P 8b03c0e5b4f64db8b7c53a3cf64ef488: UndoDeltaBlockGCOp(ba69f06a23b041838e77d4b0a9308312) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":142,"lbm_reads_lt_1ms":4}
I20260812 06:18:48.467342 13832 maintenance_manager.cc:419] P 8b03c0e5b4f64db8b7c53a3cf64ef488: Scheduling FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312): perf score=3.181125
I20260812 06:18:48.485570 13743 maintenance_manager.cc:643] P 8b03c0e5b4f64db8b7c53a3cf64ef488: FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312) complete. Timing: real 0.018s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4976,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:48.486083 13832 maintenance_manager.cc:419] P 8b03c0e5b4f64db8b7c53a3cf64ef488: Scheduling FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312): perf score=2.188937
I20260812 06:18:48.496834 13743 maintenance_manager.cc:643] P 8b03c0e5b4f64db8b7c53a3cf64ef488: FlushDeltaMemStoresOp(ba69f06a23b041838e77d4b0a9308312) complete. Timing: real 0.011s	user 0.003s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4035,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:48.497264 13832 maintenance_manager.cc:419] P 8b03c0e5b4f64db8b7c53a3cf64ef488: Scheduling MajorDeltaCompactionOp(ba69f06a23b041838e77d4b0a9308312): perf score=1.000000
I20260812 06:18:48.581315 13591 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.976s	user 1.806s	sys 0.173s
I20260812 06:18:48.694602 13591 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.113s	user 0.002s	sys 0.000s
I20260812 06:18:48.695273 13591 tablet_server.cc:179] TabletServer@127.13.69.193:0 shutting down...
I20260812 06:18:48.731876 13743 maintenance_manager.cc:643] P 8b03c0e5b4f64db8b7c53a3cf64ef488: MajorDeltaCompactionOp(ba69f06a23b041838e77d4b0a9308312) complete. Timing: real 0.234s	user 0.153s	sys 0.079s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979740,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":4625,"lbm_read_time_us":15600,"lbm_reads_lt_1ms":770,"lbm_write_time_us":41540,"lbm_writes_lt_1ms":743,"mutex_wait_us":1894,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":3584,"thread_start_us":81,"threads_started":1,"update_count":3500}
I20260812 06:18:48.732599 13591 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:48.733175 13591 tablet_replica.cc:333] T ba69f06a23b041838e77d4b0a9308312 P 8b03c0e5b4f64db8b7c53a3cf64ef488: stopping tablet replica
I20260812 06:18:48.733493 13591 raft_consensus.cc:2243] T ba69f06a23b041838e77d4b0a9308312 P 8b03c0e5b4f64db8b7c53a3cf64ef488 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:48.733783 13591 raft_consensus.cc:2272] T ba69f06a23b041838e77d4b0a9308312 P 8b03c0e5b4f64db8b7c53a3cf64ef488 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:48.750507 13591 tablet_server.cc:196] TabletServer@127.13.69.193:0 shutdown complete.
I20260812 06:18:48.788328 13591 master.cc:562] Master@127.13.69.254:37785 shutting down...
I20260812 06:18:48.792569 13591 raft_consensus.cc:2243] T 00000000000000000000000000000000 P d8debbb357b8433fa1583798fb7c144a [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:48.792824 13591 raft_consensus.cc:2272] T 00000000000000000000000000000000 P d8debbb357b8433fa1583798fb7c144a [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:48.792929 13591 tablet_replica.cc:333] T 00000000000000000000000000000000 P d8debbb357b8433fa1583798fb7c144a: stopping tablet replica
I20260812 06:18:48.805640 13591 master.cc:584] Master@127.13.69.254:37785 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5579 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:48.896379 13591 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.13.69.254:36403
I20260812 06:18:48.896857 13591 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:48.899339 13881 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:18:48.899358 13878 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:18:48.899443 13876 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:18:48.899459 13591 server_base.cc:1061] running on GCE node
I20260812 06:18:48.899732 13591 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:48.899793 13591 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:18:48.899819 13591 hybrid_clock.cc:648] HybridClock initialized: now 1786515528899818 us; error 0 us; skew 500 ppm
I20260812 06:18:48.903636 13591 webserver.cc:533] Webserver started at http://127.13.69.254:42145/ using document root <none> and password file <none>
I20260812 06:18:48.903910 13591 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:48.903998 13591 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:48.904090 13591 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:48.904515 13591 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523306816-13591-0/minicluster-data/master-0-root/instance:
uuid: "6b442a27b2c3451ca4885740aa4ad2df"
format_stamp: "Formatted at 2026-08-12 06:18:48 on dist-test-slave-x5fp"
I20260812 06:18:48.906248 13591 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:48.907328 13886 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:18:48.907606 13591 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:48.907701 13591 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523306816-13591-0/minicluster-data/master-0-root
uuid: "6b442a27b2c3451ca4885740aa4ad2df"
format_stamp: "Formatted at 2026-08-12 06:18:48 on dist-test-slave-x5fp"
I20260812 06:18:48.907790 13591 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523306816-13591-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523306816-13591-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523306816-13591-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:18:48.924342 13591 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:48.924844 13591 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:48.929160 13591 rpc_server.cc:307] RPC server started. Bound to: 127.13.69.254:36403
I20260812 06:18:48.930454 13976 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.13.69.254:36403 every 8 connection(s)
I20260812 06:18:48.936554 13978 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:18:48.942601 13978 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 6b442a27b2c3451ca4885740aa4ad2df: Bootstrap starting.
I20260812 06:18:48.943786 13978 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 6b442a27b2c3451ca4885740aa4ad2df: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:48.944922 13978 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 6b442a27b2c3451ca4885740aa4ad2df: No bootstrap required, opened a new log
I20260812 06:18:48.945279 13978 raft_consensus.cc:359] T 00000000000000000000000000000000 P 6b442a27b2c3451ca4885740aa4ad2df [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6b442a27b2c3451ca4885740aa4ad2df" member_type: VOTER }
I20260812 06:18:48.945374 13978 raft_consensus.cc:385] T 00000000000000000000000000000000 P 6b442a27b2c3451ca4885740aa4ad2df [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:48.945396 13978 raft_consensus.cc:740] T 00000000000000000000000000000000 P 6b442a27b2c3451ca4885740aa4ad2df [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 6b442a27b2c3451ca4885740aa4ad2df, State: Initialized, Role: FOLLOWER
I20260812 06:18:48.945536 13978 consensus_queue.cc:260] T 00000000000000000000000000000000 P 6b442a27b2c3451ca4885740aa4ad2df [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: "6b442a27b2c3451ca4885740aa4ad2df" member_type: VOTER }
I20260812 06:18:48.945626 13978 raft_consensus.cc:399] T 00000000000000000000000000000000 P 6b442a27b2c3451ca4885740aa4ad2df [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:48.945650 13978 raft_consensus.cc:493] T 00000000000000000000000000000000 P 6b442a27b2c3451ca4885740aa4ad2df [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:48.945681 13978 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 6b442a27b2c3451ca4885740aa4ad2df [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:48.946321 13978 raft_consensus.cc:515] T 00000000000000000000000000000000 P 6b442a27b2c3451ca4885740aa4ad2df [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6b442a27b2c3451ca4885740aa4ad2df" member_type: VOTER }
I20260812 06:18:48.946434 13978 leader_election.cc:304] T 00000000000000000000000000000000 P 6b442a27b2c3451ca4885740aa4ad2df [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: 6b442a27b2c3451ca4885740aa4ad2df; no voters: 
I20260812 06:18:48.946574 13978 leader_election.cc:290] T 00000000000000000000000000000000 P 6b442a27b2c3451ca4885740aa4ad2df [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:48.946756 13983 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 6b442a27b2c3451ca4885740aa4ad2df [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:48.946964 13983 raft_consensus.cc:697] T 00000000000000000000000000000000 P 6b442a27b2c3451ca4885740aa4ad2df [term 1 LEADER]: Becoming Leader. State: Replica: 6b442a27b2c3451ca4885740aa4ad2df, State: Running, Role: LEADER
I20260812 06:18:48.947091 13978 sys_catalog.cc:565] T 00000000000000000000000000000000 P 6b442a27b2c3451ca4885740aa4ad2df [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:48.947110 13983 consensus_queue.cc:237] T 00000000000000000000000000000000 P 6b442a27b2c3451ca4885740aa4ad2df [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: "6b442a27b2c3451ca4885740aa4ad2df" member_type: VOTER }
I20260812 06:18:48.947609 13987 sys_catalog.cc:455] T 00000000000000000000000000000000 P 6b442a27b2c3451ca4885740aa4ad2df [sys.catalog]: SysCatalogTable state changed. Reason: New leader 6b442a27b2c3451ca4885740aa4ad2df. Latest consensus state: current_term: 1 leader_uuid: "6b442a27b2c3451ca4885740aa4ad2df" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6b442a27b2c3451ca4885740aa4ad2df" member_type: VOTER } }
I20260812 06:18:48.947595 13986 sys_catalog.cc:455] T 00000000000000000000000000000000 P 6b442a27b2c3451ca4885740aa4ad2df [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "6b442a27b2c3451ca4885740aa4ad2df" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6b442a27b2c3451ca4885740aa4ad2df" member_type: VOTER } }
I20260812 06:18:48.947779 13987 sys_catalog.cc:458] T 00000000000000000000000000000000 P 6b442a27b2c3451ca4885740aa4ad2df [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:48.947794 13986 sys_catalog.cc:458] T 00000000000000000000000000000000 P 6b442a27b2c3451ca4885740aa4ad2df [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:48.948283 13995 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:48.949108 13995 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:48.949405 13591 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:48.950987 13995 catalog_manager.cc:1383] Generated new cluster ID: 185680c2e76c4d7c8c01a5759a88b595
I20260812 06:18:48.951048 13995 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:48.966792 13995 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:48.967319 13995 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:48.973340 13995 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 6b442a27b2c3451ca4885740aa4ad2df: Generated new TSK 0
I20260812 06:18:48.973498 13995 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:48.981817 13591 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:48.983783 14022 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:18:48.983889 14019 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:18:48.984037 13591 server_base.cc:1061] running on GCE node
W20260812 06:18:48.984050 14018 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:18:48.984345 13591 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:48.984390 13591 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:18:48.984405 13591 hybrid_clock.cc:648] HybridClock initialized: now 1786515528984405 us; error 0 us; skew 500 ppm
I20260812 06:18:48.985261 13591 webserver.cc:533] Webserver started at http://127.13.69.193:34591/ using document root <none> and password file <none>
I20260812 06:18:48.985410 13591 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:48.985456 13591 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:48.985520 13591 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:48.985878 13591 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523306816-13591-0/minicluster-data/ts-0-root/instance:
uuid: "ac6089a3031e462a943e291bea90f097"
format_stamp: "Formatted at 2026-08-12 06:18:48 on dist-test-slave-x5fp"
I20260812 06:18:48.987299 13591 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:48.988189 14028 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:18:48.988444 13591 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:48.988536 13591 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523306816-13591-0/minicluster-data/ts-0-root
uuid: "ac6089a3031e462a943e291bea90f097"
format_stamp: "Formatted at 2026-08-12 06:18:48 on dist-test-slave-x5fp"
I20260812 06:18:48.988621 13591 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523306816-13591-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523306816-13591-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523306816-13591-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:18:48.995362 13591 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:48.995677 13591 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:48.995960 13591 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:48.996410 13591 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:48.996470 13591 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:48.996529 13591 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:48.996563 13591 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:49.001106 13591 rpc_server.cc:307] RPC server started. Bound to: 127.13.69.193:41671
I20260812 06:18:49.001987 14138 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.13.69.193:41671 every 8 connection(s)
I20260812 06:18:49.006572 14140 heartbeater.cc:344] Connected to a master server at 127.13.69.254:36403
I20260812 06:18:49.006747 14140 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:49.006999 14140 heartbeater.cc:507] Master 127.13.69.254:36403 requested a full tablet report, sending...
I20260812 06:18:49.007683 13909 ts_manager.cc:194] Registered new tserver with Master: ac6089a3031e462a943e291bea90f097 (127.13.69.193:41671)
I20260812 06:18:49.008563 13909 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:34712
I20260812 06:18:49.008776 13591 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.006804564s
I20260812 06:18:49.015769 13909 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:34728:
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:18:49.024472 14082 tablet_service.cc:1511] Processing CreateTablet for tablet 81b5643bb80248f98b7be75397c6298f (DEFAULT_TABLE table=heavy-update-compaction-test [id=21b1dd747ed94e15acdf0fb06cdb9e96]), partition=
I20260812 06:18:49.024766 14082 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 81b5643bb80248f98b7be75397c6298f. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:49.026878 14161 tablet_bootstrap.cc:492] T 81b5643bb80248f98b7be75397c6298f P ac6089a3031e462a943e291bea90f097: Bootstrap starting.
I20260812 06:18:49.027748 14161 tablet_bootstrap.cc:654] T 81b5643bb80248f98b7be75397c6298f P ac6089a3031e462a943e291bea90f097: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:49.028896 14161 tablet_bootstrap.cc:492] T 81b5643bb80248f98b7be75397c6298f P ac6089a3031e462a943e291bea90f097: No bootstrap required, opened a new log
I20260812 06:18:49.029001 14161 ts_tablet_manager.cc:1403] T 81b5643bb80248f98b7be75397c6298f P ac6089a3031e462a943e291bea90f097: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:49.029465 14161 raft_consensus.cc:359] T 81b5643bb80248f98b7be75397c6298f P ac6089a3031e462a943e291bea90f097 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ac6089a3031e462a943e291bea90f097" member_type: VOTER last_known_addr { host: "127.13.69.193" port: 41671 } }
I20260812 06:18:49.029574 14161 raft_consensus.cc:385] T 81b5643bb80248f98b7be75397c6298f P ac6089a3031e462a943e291bea90f097 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:49.029627 14161 raft_consensus.cc:740] T 81b5643bb80248f98b7be75397c6298f P ac6089a3031e462a943e291bea90f097 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: ac6089a3031e462a943e291bea90f097, State: Initialized, Role: FOLLOWER
I20260812 06:18:49.029768 14161 consensus_queue.cc:260] T 81b5643bb80248f98b7be75397c6298f P ac6089a3031e462a943e291bea90f097 [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: "ac6089a3031e462a943e291bea90f097" member_type: VOTER last_known_addr { host: "127.13.69.193" port: 41671 } }
I20260812 06:18:49.029865 14161 raft_consensus.cc:399] T 81b5643bb80248f98b7be75397c6298f P ac6089a3031e462a943e291bea90f097 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:49.029914 14161 raft_consensus.cc:493] T 81b5643bb80248f98b7be75397c6298f P ac6089a3031e462a943e291bea90f097 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:49.029971 14161 raft_consensus.cc:3060] T 81b5643bb80248f98b7be75397c6298f P ac6089a3031e462a943e291bea90f097 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:49.030689 14161 raft_consensus.cc:515] T 81b5643bb80248f98b7be75397c6298f P ac6089a3031e462a943e291bea90f097 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ac6089a3031e462a943e291bea90f097" member_type: VOTER last_known_addr { host: "127.13.69.193" port: 41671 } }
I20260812 06:18:49.030817 14161 leader_election.cc:304] T 81b5643bb80248f98b7be75397c6298f P ac6089a3031e462a943e291bea90f097 [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: ac6089a3031e462a943e291bea90f097; no voters: 
I20260812 06:18:49.031073 14161 leader_election.cc:290] T 81b5643bb80248f98b7be75397c6298f P ac6089a3031e462a943e291bea90f097 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:49.031219 14163 raft_consensus.cc:2804] T 81b5643bb80248f98b7be75397c6298f P ac6089a3031e462a943e291bea90f097 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:49.031424 14161 ts_tablet_manager.cc:1434] T 81b5643bb80248f98b7be75397c6298f P ac6089a3031e462a943e291bea90f097: Time spent starting tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:49.031442 14140 heartbeater.cc:499] Master 127.13.69.254:36403 was elected leader, sending a full tablet report...
I20260812 06:18:49.031502 14163 raft_consensus.cc:697] T 81b5643bb80248f98b7be75397c6298f P ac6089a3031e462a943e291bea90f097 [term 1 LEADER]: Becoming Leader. State: Replica: ac6089a3031e462a943e291bea90f097, State: Running, Role: LEADER
I20260812 06:18:49.031656 14163 consensus_queue.cc:237] T 81b5643bb80248f98b7be75397c6298f P ac6089a3031e462a943e291bea90f097 [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: "ac6089a3031e462a943e291bea90f097" member_type: VOTER last_known_addr { host: "127.13.69.193" port: 41671 } }
I20260812 06:18:49.033205 13909 catalog_manager.cc:5719] T 81b5643bb80248f98b7be75397c6298f P ac6089a3031e462a943e291bea90f097 reported cstate change: term changed from 0 to 1, leader changed from <none> to ac6089a3031e462a943e291bea90f097 (127.13.69.193). New cstate: current_term: 1 leader_uuid: "ac6089a3031e462a943e291bea90f097" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ac6089a3031e462a943e291bea90f097" member_type: VOTER last_known_addr { host: "127.13.69.193" port: 41671 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:49.093043 13591 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.053s	user 0.018s	sys 0.004s
I20260812 06:18:49.252512 14141 maintenance_manager.cc:419] P ac6089a3031e462a943e291bea90f097: Scheduling FlushMRSOp(81b5643bb80248f98b7be75397c6298f): perf score=19.054940
I20260812 06:18:49.411983 14037 maintenance_manager.cc:643] P ac6089a3031e462a943e291bea90f097: FlushMRSOp(81b5643bb80248f98b7be75397c6298f) complete. Timing: real 0.159s	user 0.122s	sys 0.032s Metrics: {"bytes_written":12307489,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":72,"dirs.run_cpu_time_us":258,"dirs.run_wall_time_us":785,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":40986,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":2432,"update_count":1500}
I20260812 06:18:49.412645 14141 maintenance_manager.cc:419] P ac6089a3031e462a943e291bea90f097: Scheduling LogGCOp(81b5643bb80248f98b7be75397c6298f): free 20743880 bytes of WAL
I20260812 06:18:49.412897 14037 log_reader.cc:385] T 81b5643bb80248f98b7be75397c6298f: removed 2 log segments from log reader
I20260812 06:18:49.412961 14037 log.cc:1079] T 81b5643bb80248f98b7be75397c6298f P ac6089a3031e462a943e291bea90f097: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/81b5643bb80248f98b7be75397c6298f/wal-000000001 (ops 1-6)
I20260812 06:18:49.413015 14037 log.cc:1079] T 81b5643bb80248f98b7be75397c6298f P ac6089a3031e462a943e291bea90f097: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/81b5643bb80248f98b7be75397c6298f/wal-000000002 (ops 7-11)
I20260812 06:18:49.417387 14037 maintenance_manager.cc:643] P ac6089a3031e462a943e291bea90f097: LogGCOp(81b5643bb80248f98b7be75397c6298f) complete. Timing: real 0.005s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:18:49.417737 14141 maintenance_manager.cc:419] P ac6089a3031e462a943e291bea90f097: Scheduling FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f): perf score=2.188937
I20260812 06:18:49.431643 14037 maintenance_manager.cc:643] P ac6089a3031e462a943e291bea90f097: FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5154,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:49.432076 14141 maintenance_manager.cc:419] P ac6089a3031e462a943e291bea90f097: Scheduling UndoDeltaBlockGCOp(81b5643bb80248f98b7be75397c6298f): 16411396 bytes on disk
I20260812 06:18:49.432479 14037 maintenance_manager.cc:643] P ac6089a3031e462a943e291bea90f097: UndoDeltaBlockGCOp(81b5643bb80248f98b7be75397c6298f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4}
I20260812 06:18:49.432916 14141 maintenance_manager.cc:419] P ac6089a3031e462a943e291bea90f097: Scheduling MajorDeltaCompactionOp(81b5643bb80248f98b7be75397c6298f): perf score=1.000000
I20260812 06:18:49.592649 14037 maintenance_manager.cc:643] P ac6089a3031e462a943e291bea90f097: MajorDeltaCompactionOp(81b5643bb80248f98b7be75397c6298f) complete. Timing: real 0.160s	user 0.108s	sys 0.050s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":81,"lbm_read_time_us":10840,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27176,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"thread_start_us":269,"threads_started":5,"update_count":2000}
I20260812 06:18:49.593283 14141 maintenance_manager.cc:419] P ac6089a3031e462a943e291bea90f097: Scheduling FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f): perf score=12.110812
I20260812 06:18:49.635793 14037 maintenance_manager.cc:643] P ac6089a3031e462a943e291bea90f097: FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f) complete. Timing: real 0.042s	user 0.028s	sys 0.011s Metrics: {"bytes_written":13661280,"delete_count":0,"lbm_write_time_us":18021,"lbm_writes_lt_1ms":336,"reinsert_count":0,"update_count":1665}
I20260812 06:18:49.636297 14141 maintenance_manager.cc:419] P ac6089a3031e462a943e291bea90f097: Scheduling FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f): perf score=1.196750
I20260812 06:18:49.647179 14037 maintenance_manager.cc:643] P ac6089a3031e462a943e291bea90f097: FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":2748830,"delete_count":0,"lbm_write_time_us":3704,"lbm_writes_lt_1ms":70,"reinsert_count":0,"update_count":335}
I20260812 06:18:49.647724 14141 maintenance_manager.cc:419] P ac6089a3031e462a943e291bea90f097: Scheduling MajorDeltaCompactionOp(81b5643bb80248f98b7be75397c6298f): perf score=1.000000
I20260812 06:18:49.801318 14037 maintenance_manager.cc:643] P ac6089a3031e462a943e291bea90f097: MajorDeltaCompactionOp(81b5643bb80248f98b7be75397c6298f) complete. Timing: real 0.153s	user 0.102s	sys 0.046s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672238,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1214,"lbm_read_time_us":9799,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24935,"lbm_writes_lt_1ms":443,"mutex_wait_us":413,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2000}
I20260812 06:18:49.802026 14141 maintenance_manager.cc:419] P ac6089a3031e462a943e291bea90f097: Scheduling FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f): perf score=14.095187
I20260812 06:18:49.855943 14037 maintenance_manager.cc:643] P ac6089a3031e462a943e291bea90f097: FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f) complete. Timing: real 0.054s	user 0.017s	sys 0.029s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22253,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:49.856482 14141 maintenance_manager.cc:419] P ac6089a3031e462a943e291bea90f097: Scheduling FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f): perf score=2.188937
I20260812 06:18:49.876281 14037 maintenance_manager.cc:643] P ac6089a3031e462a943e291bea90f097: FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f) complete. Timing: real 0.020s	user 0.009s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3901,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:49.876959 14141 maintenance_manager.cc:419] P ac6089a3031e462a943e291bea90f097: Scheduling MajorDeltaCompactionOp(81b5643bb80248f98b7be75397c6298f): perf score=1.000000
I20260812 06:18:50.061691 14037 maintenance_manager.cc:643] P ac6089a3031e462a943e291bea90f097: MajorDeltaCompactionOp(81b5643bb80248f98b7be75397c6298f) complete. Timing: real 0.185s	user 0.132s	sys 0.053s 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":320,"lbm_read_time_us":12725,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30341,"lbm_writes_lt_1ms":543,"mutex_wait_us":20,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8448,"update_count":2500}
I20260812 06:18:50.062371 14141 maintenance_manager.cc:419] P ac6089a3031e462a943e291bea90f097: Scheduling FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f): perf score=14.095187
I20260812 06:18:50.112528 14037 maintenance_manager.cc:643] P ac6089a3031e462a943e291bea90f097: FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f) complete. Timing: real 0.050s	user 0.020s	sys 0.019s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":19324,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:50.113062 14141 maintenance_manager.cc:419] P ac6089a3031e462a943e291bea90f097: Scheduling FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f): perf score=2.188937
I20260812 06:18:50.123287 14037 maintenance_manager.cc:643] P ac6089a3031e462a943e291bea90f097: FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4015,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:50.123739 14141 maintenance_manager.cc:419] P ac6089a3031e462a943e291bea90f097: Scheduling MajorDeltaCompactionOp(81b5643bb80248f98b7be75397c6298f): perf score=1.000000
I20260812 06:18:50.301819 14037 maintenance_manager.cc:643] P ac6089a3031e462a943e291bea90f097: MajorDeltaCompactionOp(81b5643bb80248f98b7be75397c6298f) complete. Timing: real 0.178s	user 0.125s	sys 0.048s 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":236,"lbm_read_time_us":12106,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29187,"lbm_writes_lt_1ms":543,"mutex_wait_us":24,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9728,"update_count":2500}
I20260812 06:18:50.302516 14141 maintenance_manager.cc:419] P ac6089a3031e462a943e291bea90f097: Scheduling FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f): perf score=11.118625
I20260812 06:18:50.339807 14037 maintenance_manager.cc:643] P ac6089a3031e462a943e291bea90f097: FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f) complete. Timing: real 0.037s	user 0.026s	sys 0.008s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":15652,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:50.340399 14141 maintenance_manager.cc:419] P ac6089a3031e462a943e291bea90f097: Scheduling FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f): perf score=2.188937
I20260812 06:18:50.356379 14037 maintenance_manager.cc:643] P ac6089a3031e462a943e291bea90f097: FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f) complete. Timing: real 0.016s	user 0.004s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5469,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:50.357002 14141 maintenance_manager.cc:419] P ac6089a3031e462a943e291bea90f097: Scheduling MajorDeltaCompactionOp(81b5643bb80248f98b7be75397c6298f): perf score=1.000000
I20260812 06:18:50.487591 14037 maintenance_manager.cc:643] P ac6089a3031e462a943e291bea90f097: MajorDeltaCompactionOp(81b5643bb80248f98b7be75397c6298f) complete. Timing: real 0.130s	user 0.089s	sys 0.041s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672270,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":101,"lbm_read_time_us":7902,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26321,"lbm_writes_lt_1ms":443,"mutex_wait_us":24,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12032,"update_count":2000}
I20260812 06:18:50.488147 14141 maintenance_manager.cc:419] P ac6089a3031e462a943e291bea90f097: Scheduling FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f): perf score=10.126437
I20260812 06:18:50.525702 14037 maintenance_manager.cc:643] P ac6089a3031e462a943e291bea90f097: FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f) complete. Timing: real 0.037s	user 0.030s	sys 0.000s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":13376,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:50.526227 14141 maintenance_manager.cc:419] P ac6089a3031e462a943e291bea90f097: Scheduling FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f): perf score=2.188937
I20260812 06:18:50.540935 14037 maintenance_manager.cc:643] P ac6089a3031e462a943e291bea90f097: FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f) complete. Timing: real 0.015s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5600,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:50.541461 14141 maintenance_manager.cc:419] P ac6089a3031e462a943e291bea90f097: Scheduling MajorDeltaCompactionOp(81b5643bb80248f98b7be75397c6298f): perf score=1.000000
I20260812 06:18:50.671695 14037 maintenance_manager.cc:643] P ac6089a3031e462a943e291bea90f097: MajorDeltaCompactionOp(81b5643bb80248f98b7be75397c6298f) complete. Timing: real 0.130s	user 0.106s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":854,"lbm_read_time_us":9123,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25458,"lbm_writes_lt_1ms":443,"mutex_wait_us":43,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":21120,"update_count":2000}
I20260812 06:18:50.672243 14141 maintenance_manager.cc:419] P ac6089a3031e462a943e291bea90f097: Scheduling FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f): perf score=10.126437
I20260812 06:18:50.722921 14037 maintenance_manager.cc:643] P ac6089a3031e462a943e291bea90f097: FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f) complete. Timing: real 0.050s	user 0.009s	sys 0.031s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14758,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:50.723440 14141 maintenance_manager.cc:419] P ac6089a3031e462a943e291bea90f097: Scheduling FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f): perf score=2.188937
I20260812 06:18:50.733902 14037 maintenance_manager.cc:643] P ac6089a3031e462a943e291bea90f097: FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4101,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:50.734365 14141 maintenance_manager.cc:419] P ac6089a3031e462a943e291bea90f097: Scheduling FlushMRSOp(81b5643bb80248f98b7be75397c6298f): perf score=1.000000
I20260812 06:18:50.775925 14037 maintenance_manager.cc:643] P ac6089a3031e462a943e291bea90f097: FlushMRSOp(81b5643bb80248f98b7be75397c6298f) complete. Timing: real 0.041s	user 0.028s	sys 0.003s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":88,"dirs.run_cpu_time_us":216,"dirs.run_wall_time_us":1461,"drs_written":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1974,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:50.776522 14141 maintenance_manager.cc:419] P ac6089a3031e462a943e291bea90f097: Scheduling LogGCOp(81b5643bb80248f98b7be75397c6298f): free 120100331 bytes of WAL
I20260812 06:18:50.776804 14037 log_reader.cc:385] T 81b5643bb80248f98b7be75397c6298f: removed 12 log segments from log reader
I20260812 06:18:50.776870 14037 log.cc:1079] T 81b5643bb80248f98b7be75397c6298f P ac6089a3031e462a943e291bea90f097: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/81b5643bb80248f98b7be75397c6298f/wal-000000003 (ops 12-16)
I20260812 06:18:50.776921 14037 log.cc:1079] T 81b5643bb80248f98b7be75397c6298f P ac6089a3031e462a943e291bea90f097: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/81b5643bb80248f98b7be75397c6298f/wal-000000004 (ops 17-20)
I20260812 06:18:50.776976 14037 log.cc:1079] T 81b5643bb80248f98b7be75397c6298f P ac6089a3031e462a943e291bea90f097: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/81b5643bb80248f98b7be75397c6298f/wal-000000005 (ops 21-25)
I20260812 06:18:50.777015 14037 log.cc:1079] T 81b5643bb80248f98b7be75397c6298f P ac6089a3031e462a943e291bea90f097: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/81b5643bb80248f98b7be75397c6298f/wal-000000006 (ops 26-30)
I20260812 06:18:50.777053 14037 log.cc:1079] T 81b5643bb80248f98b7be75397c6298f P ac6089a3031e462a943e291bea90f097: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/81b5643bb80248f98b7be75397c6298f/wal-000000007 (ops 31-34)
I20260812 06:18:50.777089 14037 log.cc:1079] T 81b5643bb80248f98b7be75397c6298f P ac6089a3031e462a943e291bea90f097: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/81b5643bb80248f98b7be75397c6298f/wal-000000008 (ops 35-39)
I20260812 06:18:50.777127 14037 log.cc:1079] T 81b5643bb80248f98b7be75397c6298f P ac6089a3031e462a943e291bea90f097: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/81b5643bb80248f98b7be75397c6298f/wal-000000009 (ops 40-44)
I20260812 06:18:50.777163 14037 log.cc:1079] T 81b5643bb80248f98b7be75397c6298f P ac6089a3031e462a943e291bea90f097: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/81b5643bb80248f98b7be75397c6298f/wal-000000010 (ops 45-48)
I20260812 06:18:50.777199 14037 log.cc:1079] T 81b5643bb80248f98b7be75397c6298f P ac6089a3031e462a943e291bea90f097: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/81b5643bb80248f98b7be75397c6298f/wal-000000011 (ops 49-53)
I20260812 06:18:50.777235 14037 log.cc:1079] T 81b5643bb80248f98b7be75397c6298f P ac6089a3031e462a943e291bea90f097: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/81b5643bb80248f98b7be75397c6298f/wal-000000012 (ops 54-58)
I20260812 06:18:50.777271 14037 log.cc:1079] T 81b5643bb80248f98b7be75397c6298f P ac6089a3031e462a943e291bea90f097: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/81b5643bb80248f98b7be75397c6298f/wal-000000013 (ops 59-63)
I20260812 06:18:50.777307 14037 log.cc:1079] T 81b5643bb80248f98b7be75397c6298f P ac6089a3031e462a943e291bea90f097: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/81b5643bb80248f98b7be75397c6298f/wal-000000014 (ops 64-68)
I20260812 06:18:50.804797 14037 maintenance_manager.cc:643] P ac6089a3031e462a943e291bea90f097: LogGCOp(81b5643bb80248f98b7be75397c6298f) complete. Timing: real 0.028s	user 0.005s	sys 0.023s Metrics: {}
I20260812 06:18:50.805194 14141 maintenance_manager.cc:419] P ac6089a3031e462a943e291bea90f097: Scheduling FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f): perf score=2.188937
I20260812 06:18:50.827884 14037 maintenance_manager.cc:643] P ac6089a3031e462a943e291bea90f097: FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f) complete. Timing: real 0.023s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6108,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:50.828310 14141 maintenance_manager.cc:419] P ac6089a3031e462a943e291bea90f097: Scheduling UndoDeltaBlockGCOp(81b5643bb80248f98b7be75397c6298f): 472 bytes on disk
I20260812 06:18:50.828680 14037 maintenance_manager.cc:643] P ac6089a3031e462a943e291bea90f097: UndoDeltaBlockGCOp(81b5643bb80248f98b7be75397c6298f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4}
I20260812 06:18:50.829183 14141 maintenance_manager.cc:419] P ac6089a3031e462a943e291bea90f097: Scheduling FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f): perf score=2.188937
I20260812 06:18:50.839272 14037 maintenance_manager.cc:643] P ac6089a3031e462a943e291bea90f097: FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f) complete. Timing: real 0.010s	user 0.005s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3993,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:50.839764 14141 maintenance_manager.cc:419] P ac6089a3031e462a943e291bea90f097: Scheduling MajorDeltaCompactionOp(81b5643bb80248f98b7be75397c6298f): perf score=1.000000
I20260812 06:18:51.052665 14037 maintenance_manager.cc:643] P ac6089a3031e462a943e291bea90f097: MajorDeltaCompactionOp(81b5643bb80248f98b7be75397c6298f) complete. Timing: real 0.213s	user 0.126s	sys 0.083s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877337,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":2658,"lbm_read_time_us":14798,"lbm_reads_lt_1ms":674,"lbm_write_time_us":34106,"lbm_writes_lt_1ms":643,"mutex_wait_us":2318,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":13824,"thread_start_us":85,"threads_started":1,"update_count":3000}
I20260812 06:18:51.053457 14141 maintenance_manager.cc:419] P ac6089a3031e462a943e291bea90f097: Scheduling FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f): perf score=14.095187
I20260812 06:18:51.124220 14037 maintenance_manager.cc:643] P ac6089a3031e462a943e291bea90f097: FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f) complete. Timing: real 0.070s	user 0.037s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":26218,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:51.124753 14141 maintenance_manager.cc:419] P ac6089a3031e462a943e291bea90f097: Scheduling FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f): perf score=2.188937
I20260812 06:18:51.135051 14037 maintenance_manager.cc:643] P ac6089a3031e462a943e291bea90f097: FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3786,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:51.135913 14141 maintenance_manager.cc:419] P ac6089a3031e462a943e291bea90f097: Scheduling MajorDeltaCompactionOp(81b5643bb80248f98b7be75397c6298f): perf score=1.000000
I20260812 06:18:51.312862 14037 maintenance_manager.cc:643] P ac6089a3031e462a943e291bea90f097: MajorDeltaCompactionOp(81b5643bb80248f98b7be75397c6298f) complete. Timing: real 0.177s	user 0.108s	sys 0.067s 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":1344,"lbm_read_time_us":12926,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28336,"lbm_writes_lt_1ms":543,"mutex_wait_us":335,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":2500}
I20260812 06:18:51.313578 14141 maintenance_manager.cc:419] P ac6089a3031e462a943e291bea90f097: Scheduling FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f): perf score=14.095187
I20260812 06:18:51.371124 14037 maintenance_manager.cc:643] P ac6089a3031e462a943e291bea90f097: FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f) complete. Timing: real 0.057s	user 0.033s	sys 0.022s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":20675,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:51.371634 14141 maintenance_manager.cc:419] P ac6089a3031e462a943e291bea90f097: Scheduling FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f): perf score=2.188937
I20260812 06:18:51.387715 14037 maintenance_manager.cc:643] P ac6089a3031e462a943e291bea90f097: FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f) complete. Timing: real 0.016s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6239,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":500}
I20260812 06:18:51.388255 14141 maintenance_manager.cc:419] P ac6089a3031e462a943e291bea90f097: Scheduling MajorDeltaCompactionOp(81b5643bb80248f98b7be75397c6298f): perf score=1.000000
I20260812 06:18:51.570634 14037 maintenance_manager.cc:643] P ac6089a3031e462a943e291bea90f097: MajorDeltaCompactionOp(81b5643bb80248f98b7be75397c6298f) complete. Timing: real 0.182s	user 0.112s	sys 0.070s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":704,"lbm_read_time_us":11625,"lbm_reads_lt_1ms":564,"lbm_write_time_us":31487,"lbm_writes_lt_1ms":543,"mutex_wait_us":320,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:18:51.571261 14141 maintenance_manager.cc:419] P ac6089a3031e462a943e291bea90f097: Scheduling FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f): perf score=14.095187
I20260812 06:18:51.623062 14037 maintenance_manager.cc:643] P ac6089a3031e462a943e291bea90f097: FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f) complete. Timing: real 0.052s	user 0.013s	sys 0.036s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17605,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:51.623721 14141 maintenance_manager.cc:419] P ac6089a3031e462a943e291bea90f097: Scheduling FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f): perf score=2.188937
I20260812 06:18:51.634706 14037 maintenance_manager.cc:643] P ac6089a3031e462a943e291bea90f097: FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4211,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:51.635175 14141 maintenance_manager.cc:419] P ac6089a3031e462a943e291bea90f097: Scheduling MajorDeltaCompactionOp(81b5643bb80248f98b7be75397c6298f): perf score=1.000000
I20260812 06:18:51.821224 14037 maintenance_manager.cc:643] P ac6089a3031e462a943e291bea90f097: MajorDeltaCompactionOp(81b5643bb80248f98b7be75397c6298f) complete. Timing: real 0.186s	user 0.123s	sys 0.052s 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":198,"lbm_read_time_us":12901,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31015,"lbm_writes_lt_1ms":543,"mutex_wait_us":44,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8960,"update_count":2500}
I20260812 06:18:51.821949 14141 maintenance_manager.cc:419] P ac6089a3031e462a943e291bea90f097: Scheduling FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f): perf score=14.095187
I20260812 06:18:51.873574 14037 maintenance_manager.cc:643] P ac6089a3031e462a943e291bea90f097: FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f) complete. Timing: real 0.051s	user 0.037s	sys 0.008s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20578,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:51.874065 14141 maintenance_manager.cc:419] P ac6089a3031e462a943e291bea90f097: Scheduling FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f): perf score=2.188937
I20260812 06:18:51.894887 14037 maintenance_manager.cc:643] P ac6089a3031e462a943e291bea90f097: FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f) complete. Timing: real 0.021s	user 0.001s	sys 0.018s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4232,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:51.895507 14141 maintenance_manager.cc:419] P ac6089a3031e462a943e291bea90f097: Scheduling MajorDeltaCompactionOp(81b5643bb80248f98b7be75397c6298f): perf score=1.000000
I20260812 06:18:52.081053 14037 maintenance_manager.cc:643] P ac6089a3031e462a943e291bea90f097: MajorDeltaCompactionOp(81b5643bb80248f98b7be75397c6298f) complete. Timing: real 0.185s	user 0.129s	sys 0.053s 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":344,"lbm_read_time_us":12326,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31261,"lbm_writes_lt_1ms":543,"mutex_wait_us":57,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2500}
I20260812 06:18:52.081760 14141 maintenance_manager.cc:419] P ac6089a3031e462a943e291bea90f097: Scheduling FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f): perf score=14.095187
I20260812 06:18:52.132601 14037 maintenance_manager.cc:643] P ac6089a3031e462a943e291bea90f097: FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f) complete. Timing: real 0.051s	user 0.023s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24352,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:18:52.133217 14141 maintenance_manager.cc:419] P ac6089a3031e462a943e291bea90f097: Scheduling FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f): perf score=2.188937
I20260812 06:18:52.159174 14037 maintenance_manager.cc:643] P ac6089a3031e462a943e291bea90f097: FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f) complete. Timing: real 0.026s	user 0.013s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6054,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:52.160048 14141 maintenance_manager.cc:419] P ac6089a3031e462a943e291bea90f097: Scheduling FlushMRSOp(81b5643bb80248f98b7be75397c6298f): perf score=1.000000
I20260812 06:18:52.209700 14037 maintenance_manager.cc:643] P ac6089a3031e462a943e291bea90f097: FlushMRSOp(81b5643bb80248f98b7be75397c6298f) complete. Timing: real 0.049s	user 0.033s	sys 0.000s Metrics: {"bytes_written":1152514,"cfile_init":1,"dirs.queue_time_us":76,"dirs.run_cpu_time_us":326,"dirs.run_wall_time_us":1422,"drs_written":1,"lbm_read_time_us":68,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1731,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28,"spinlock_wait_cycles":768}
I20260812 06:18:52.210389 14141 maintenance_manager.cc:419] P ac6089a3031e462a943e291bea90f097: Scheduling FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f): perf score=3.181125
I20260812 06:18:52.224565 14037 maintenance_manager.cc:643] P ac6089a3031e462a943e291bea90f097: FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f) complete. Timing: real 0.014s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4321,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:52.225036 14141 maintenance_manager.cc:419] P ac6089a3031e462a943e291bea90f097: Scheduling LogGCOp(81b5643bb80248f98b7be75397c6298f): free 121006432 bytes of WAL
I20260812 06:18:52.225253 14037 log_reader.cc:385] T 81b5643bb80248f98b7be75397c6298f: removed 12 log segments from log reader
I20260812 06:18:52.225301 14037 log.cc:1079] T 81b5643bb80248f98b7be75397c6298f P ac6089a3031e462a943e291bea90f097: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/81b5643bb80248f98b7be75397c6298f/wal-000000015 (ops 69-73)
I20260812 06:18:52.225353 14037 log.cc:1079] T 81b5643bb80248f98b7be75397c6298f P ac6089a3031e462a943e291bea90f097: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/81b5643bb80248f98b7be75397c6298f/wal-000000016 (ops 74-78)
I20260812 06:18:52.225399 14037 log.cc:1079] T 81b5643bb80248f98b7be75397c6298f P ac6089a3031e462a943e291bea90f097: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/81b5643bb80248f98b7be75397c6298f/wal-000000017 (ops 79-83)
I20260812 06:18:52.225430 14037 log.cc:1079] T 81b5643bb80248f98b7be75397c6298f P ac6089a3031e462a943e291bea90f097: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/81b5643bb80248f98b7be75397c6298f/wal-000000018 (ops 84-88)
I20260812 06:18:52.225474 14037 log.cc:1079] T 81b5643bb80248f98b7be75397c6298f P ac6089a3031e462a943e291bea90f097: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/81b5643bb80248f98b7be75397c6298f/wal-000000019 (ops 89-93)
I20260812 06:18:52.225517 14037 log.cc:1079] T 81b5643bb80248f98b7be75397c6298f P ac6089a3031e462a943e291bea90f097: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/81b5643bb80248f98b7be75397c6298f/wal-000000020 (ops 94-98)
I20260812 06:18:52.225553 14037 log.cc:1079] T 81b5643bb80248f98b7be75397c6298f P ac6089a3031e462a943e291bea90f097: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/81b5643bb80248f98b7be75397c6298f/wal-000000021 (ops 99-102)
I20260812 06:18:52.225611 14037 log.cc:1079] T 81b5643bb80248f98b7be75397c6298f P ac6089a3031e462a943e291bea90f097: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/81b5643bb80248f98b7be75397c6298f/wal-000000022 (ops 103-107)
I20260812 06:18:52.225652 14037 log.cc:1079] T 81b5643bb80248f98b7be75397c6298f P ac6089a3031e462a943e291bea90f097: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/81b5643bb80248f98b7be75397c6298f/wal-000000023 (ops 108-112)
I20260812 06:18:52.225692 14037 log.cc:1079] T 81b5643bb80248f98b7be75397c6298f P ac6089a3031e462a943e291bea90f097: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/81b5643bb80248f98b7be75397c6298f/wal-000000024 (ops 113-117)
I20260812 06:18:52.225732 14037 log.cc:1079] T 81b5643bb80248f98b7be75397c6298f P ac6089a3031e462a943e291bea90f097: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/81b5643bb80248f98b7be75397c6298f/wal-000000025 (ops 118-122)
I20260812 06:18:52.225771 14037 log.cc:1079] T 81b5643bb80248f98b7be75397c6298f P ac6089a3031e462a943e291bea90f097: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/81b5643bb80248f98b7be75397c6298f/wal-000000026 (ops 123-127)
I20260812 06:18:52.253422 14037 maintenance_manager.cc:643] P ac6089a3031e462a943e291bea90f097: LogGCOp(81b5643bb80248f98b7be75397c6298f) complete. Timing: real 0.028s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:18:52.253896 14141 maintenance_manager.cc:419] P ac6089a3031e462a943e291bea90f097: Scheduling UndoDeltaBlockGCOp(81b5643bb80248f98b7be75397c6298f): 447 bytes on disk
I20260812 06:18:52.254341 14037 maintenance_manager.cc:643] P ac6089a3031e462a943e291bea90f097: UndoDeltaBlockGCOp(81b5643bb80248f98b7be75397c6298f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4}
I20260812 06:18:52.254865 14141 maintenance_manager.cc:419] P ac6089a3031e462a943e291bea90f097: Scheduling FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f): perf score=2.188937
I20260812 06:18:52.268371 14037 maintenance_manager.cc:643] P ac6089a3031e462a943e291bea90f097: FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f) complete. Timing: real 0.013s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3909,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:52.268831 14141 maintenance_manager.cc:419] P ac6089a3031e462a943e291bea90f097: Scheduling FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f): perf score=2.188937
I20260812 06:18:52.278039 14037 maintenance_manager.cc:643] P ac6089a3031e462a943e291bea90f097: FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f) complete. Timing: real 0.009s	user 0.003s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3464,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:52.278499 14141 maintenance_manager.cc:419] P ac6089a3031e462a943e291bea90f097: Scheduling MajorDeltaCompactionOp(81b5643bb80248f98b7be75397c6298f): perf score=1.000000
I20260812 06:18:52.525884 14037 maintenance_manager.cc:643] P ac6089a3031e462a943e291bea90f097: MajorDeltaCompactionOp(81b5643bb80248f98b7be75397c6298f) complete. Timing: real 0.247s	user 0.160s	sys 0.083s Metrics: {"cfile_cache_miss":835,"cfile_cache_miss_bytes":37082270,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":600,"dirs.run_cpu_time_us":1602,"dirs.run_wall_time_us":12637,"lbm_read_time_us":18571,"lbm_reads_lt_1ms":875,"lbm_write_time_us":45221,"lbm_writes_lt_1ms":843,"mutex_wait_us":40,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":4992,"update_count":4000}
I20260812 06:18:52.526650 14141 maintenance_manager.cc:419] P ac6089a3031e462a943e291bea90f097: Scheduling FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f): perf score=18.063937
I20260812 06:18:52.590960 14037 maintenance_manager.cc:643] P ac6089a3031e462a943e291bea90f097: FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f) complete. Timing: real 0.061s	user 0.054s	sys 0.005s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":26999,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:52.591485 14141 maintenance_manager.cc:419] P ac6089a3031e462a943e291bea90f097: Scheduling FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f): perf score=3.181125
I20260812 06:18:52.608309 14037 maintenance_manager.cc:643] P ac6089a3031e462a943e291bea90f097: FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f) complete. Timing: real 0.017s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4548,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:52.608876 14141 maintenance_manager.cc:419] P ac6089a3031e462a943e291bea90f097: Scheduling FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f): perf score=2.188937
I20260812 06:18:52.618686 14037 maintenance_manager.cc:643] P ac6089a3031e462a943e291bea90f097: FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3631,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:52.619174 14141 maintenance_manager.cc:419] P ac6089a3031e462a943e291bea90f097: Scheduling MajorDeltaCompactionOp(81b5643bb80248f98b7be75397c6298f): perf score=1.000000
I20260812 06:18:52.802218 14037 maintenance_manager.cc:643] P ac6089a3031e462a943e291bea90f097: MajorDeltaCompactionOp(81b5643bb80248f98b7be75397c6298f) complete. Timing: real 0.183s	user 0.144s	sys 0.039s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":32979623,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":93,"lbm_read_time_us":13445,"lbm_reads_lt_1ms":773,"lbm_write_time_us":38199,"lbm_writes_lt_1ms":743,"mutex_wait_us":27,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":14848,"thread_start_us":90,"threads_started":1,"update_count":3500}
I20260812 06:18:52.802855 14141 maintenance_manager.cc:419] P ac6089a3031e462a943e291bea90f097: Scheduling FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f): perf score=14.095187
I20260812 06:18:52.850054 14037 maintenance_manager.cc:643] P ac6089a3031e462a943e291bea90f097: FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f) complete. Timing: real 0.047s	user 0.038s	sys 0.008s Metrics: {"bytes_written":16409897,"delete_count":0,"lbm_write_time_us":20931,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":4864,"update_count":2000}
I20260812 06:18:52.850626 14141 maintenance_manager.cc:419] P ac6089a3031e462a943e291bea90f097: Scheduling FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f): perf score=2.188937
I20260812 06:18:52.865319 14037 maintenance_manager.cc:643] P ac6089a3031e462a943e291bea90f097: FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f) complete. Timing: real 0.014s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4949,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:52.865916 14141 maintenance_manager.cc:419] P ac6089a3031e462a943e291bea90f097: Scheduling MajorDeltaCompactionOp(81b5643bb80248f98b7be75397c6298f): perf score=1.000000
I20260812 06:18:53.038076 14037 maintenance_manager.cc:643] P ac6089a3031e462a943e291bea90f097: MajorDeltaCompactionOp(81b5643bb80248f98b7be75397c6298f) complete. Timing: real 0.172s	user 0.116s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":440,"lbm_read_time_us":11288,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32152,"lbm_writes_lt_1ms":543,"mutex_wait_us":78,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:18:53.038764 14141 maintenance_manager.cc:419] P ac6089a3031e462a943e291bea90f097: Scheduling FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f): perf score=14.095187
I20260812 06:18:53.102774 14037 maintenance_manager.cc:643] P ac6089a3031e462a943e291bea90f097: FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f) complete. Timing: real 0.064s	user 0.033s	sys 0.016s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":22326,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:18:53.103353 14141 maintenance_manager.cc:419] P ac6089a3031e462a943e291bea90f097: Scheduling FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f): perf score=2.188937
I20260812 06:18:53.115265 14037 maintenance_manager.cc:643] P ac6089a3031e462a943e291bea90f097: FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4314,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:53.115854 14141 maintenance_manager.cc:419] P ac6089a3031e462a943e291bea90f097: Scheduling MajorDeltaCompactionOp(81b5643bb80248f98b7be75397c6298f): perf score=1.000000
I20260812 06:18:53.288231 14037 maintenance_manager.cc:643] P ac6089a3031e462a943e291bea90f097: MajorDeltaCompactionOp(81b5643bb80248f98b7be75397c6298f) complete. Timing: real 0.172s	user 0.122s	sys 0.045s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":983,"lbm_read_time_us":11701,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28906,"lbm_writes_lt_1ms":543,"mutex_wait_us":397,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":18432,"update_count":2500}
I20260812 06:18:53.288902 14141 maintenance_manager.cc:419] P ac6089a3031e462a943e291bea90f097: Scheduling FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f): perf score=14.095187
I20260812 06:18:53.339509 14037 maintenance_manager.cc:643] P ac6089a3031e462a943e291bea90f097: FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f) complete. Timing: real 0.050s	user 0.031s	sys 0.017s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21767,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:53.340081 14141 maintenance_manager.cc:419] P ac6089a3031e462a943e291bea90f097: Scheduling FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f): perf score=2.188937
I20260812 06:18:53.352445 14037 maintenance_manager.cc:643] P ac6089a3031e462a943e291bea90f097: FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4268,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:53.353087 14141 maintenance_manager.cc:419] P ac6089a3031e462a943e291bea90f097: Scheduling MajorDeltaCompactionOp(81b5643bb80248f98b7be75397c6298f): perf score=1.000000
I20260812 06:18:53.519037 14037 maintenance_manager.cc:643] P ac6089a3031e462a943e291bea90f097: MajorDeltaCompactionOp(81b5643bb80248f98b7be75397c6298f) complete. Timing: real 0.166s	user 0.113s	sys 0.053s 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":188,"lbm_read_time_us":12776,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26271,"lbm_writes_lt_1ms":543,"mutex_wait_us":42,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2500}
I20260812 06:18:53.519821 14141 maintenance_manager.cc:419] P ac6089a3031e462a943e291bea90f097: Scheduling FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f): perf score=14.095187
I20260812 06:18:53.585606 14037 maintenance_manager.cc:643] P ac6089a3031e462a943e291bea90f097: FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f) complete. Timing: real 0.066s	user 0.035s	sys 0.027s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":26226,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:18:53.586097 14141 maintenance_manager.cc:419] P ac6089a3031e462a943e291bea90f097: Scheduling FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f): perf score=3.181125
I20260812 06:18:53.598272 14037 maintenance_manager.cc:643] P ac6089a3031e462a943e291bea90f097: FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f) complete. Timing: real 0.012s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":4618,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:53.598791 14141 maintenance_manager.cc:419] P ac6089a3031e462a943e291bea90f097: Scheduling FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f): perf score=2.188937
I20260812 06:18:53.612030 14037 maintenance_manager.cc:643] P ac6089a3031e462a943e291bea90f097: FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5008,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:53.612573 14141 maintenance_manager.cc:419] P ac6089a3031e462a943e291bea90f097: Scheduling FlushMRSOp(81b5643bb80248f98b7be75397c6298f): perf score=1.000000
I20260812 06:18:53.649890 14037 maintenance_manager.cc:643] P ac6089a3031e462a943e291bea90f097: FlushMRSOp(81b5643bb80248f98b7be75397c6298f) complete. Timing: real 0.037s	user 0.035s	sys 0.001s Metrics: {"bytes_written":1234475,"cfile_init":1,"dirs.queue_time_us":60,"dirs.run_cpu_time_us":237,"dirs.run_wall_time_us":1327,"drs_written":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2172,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:53.650676 14141 maintenance_manager.cc:419] P ac6089a3031e462a943e291bea90f097: Scheduling LogGCOp(81b5643bb80248f98b7be75397c6298f): free 121006694 bytes of WAL
I20260812 06:18:53.650985 14037 log_reader.cc:385] T 81b5643bb80248f98b7be75397c6298f: removed 12 log segments from log reader
I20260812 06:18:53.651060 14037 log.cc:1079] T 81b5643bb80248f98b7be75397c6298f P ac6089a3031e462a943e291bea90f097: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/81b5643bb80248f98b7be75397c6298f/wal-000000027 (ops 128-132)
I20260812 06:18:53.651118 14037 log.cc:1079] T 81b5643bb80248f98b7be75397c6298f P ac6089a3031e462a943e291bea90f097: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/81b5643bb80248f98b7be75397c6298f/wal-000000028 (ops 133-137)
I20260812 06:18:53.651176 14037 log.cc:1079] T 81b5643bb80248f98b7be75397c6298f P ac6089a3031e462a943e291bea90f097: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/81b5643bb80248f98b7be75397c6298f/wal-000000029 (ops 138-142)
I20260812 06:18:53.651222 14037 log.cc:1079] T 81b5643bb80248f98b7be75397c6298f P ac6089a3031e462a943e291bea90f097: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/81b5643bb80248f98b7be75397c6298f/wal-000000030 (ops 143-147)
I20260812 06:18:53.651260 14037 log.cc:1079] T 81b5643bb80248f98b7be75397c6298f P ac6089a3031e462a943e291bea90f097: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/81b5643bb80248f98b7be75397c6298f/wal-000000031 (ops 148-152)
I20260812 06:18:53.651298 14037 log.cc:1079] T 81b5643bb80248f98b7be75397c6298f P ac6089a3031e462a943e291bea90f097: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/81b5643bb80248f98b7be75397c6298f/wal-000000032 (ops 153-156)
I20260812 06:18:53.651338 14037 log.cc:1079] T 81b5643bb80248f98b7be75397c6298f P ac6089a3031e462a943e291bea90f097: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/81b5643bb80248f98b7be75397c6298f/wal-000000033 (ops 157-161)
I20260812 06:18:53.651374 14037 log.cc:1079] T 81b5643bb80248f98b7be75397c6298f P ac6089a3031e462a943e291bea90f097: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/81b5643bb80248f98b7be75397c6298f/wal-000000034 (ops 162-166)
I20260812 06:18:53.651412 14037 log.cc:1079] T 81b5643bb80248f98b7be75397c6298f P ac6089a3031e462a943e291bea90f097: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/81b5643bb80248f98b7be75397c6298f/wal-000000035 (ops 167-171)
I20260812 06:18:53.651451 14037 log.cc:1079] T 81b5643bb80248f98b7be75397c6298f P ac6089a3031e462a943e291bea90f097: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/81b5643bb80248f98b7be75397c6298f/wal-000000036 (ops 172-176)
I20260812 06:18:53.651489 14037 log.cc:1079] T 81b5643bb80248f98b7be75397c6298f P ac6089a3031e462a943e291bea90f097: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/81b5643bb80248f98b7be75397c6298f/wal-000000037 (ops 177-181)
I20260812 06:18:53.651525 14037 log.cc:1079] T 81b5643bb80248f98b7be75397c6298f P ac6089a3031e462a943e291bea90f097: Deleting log segment in path: /tmp/dist-test-taskn7DJsU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523306816-13591-0/minicluster-data/ts-0-root/wals/81b5643bb80248f98b7be75397c6298f/wal-000000038 (ops 182-186)
I20260812 06:18:53.678889 14037 maintenance_manager.cc:643] P ac6089a3031e462a943e291bea90f097: LogGCOp(81b5643bb80248f98b7be75397c6298f) complete. Timing: real 0.028s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:18:53.679375 14141 maintenance_manager.cc:419] P ac6089a3031e462a943e291bea90f097: Scheduling UndoDeltaBlockGCOp(81b5643bb80248f98b7be75397c6298f): 473 bytes on disk
I20260812 06:18:53.679903 14037 maintenance_manager.cc:643] P ac6089a3031e462a943e291bea90f097: UndoDeltaBlockGCOp(81b5643bb80248f98b7be75397c6298f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":89,"lbm_reads_lt_1ms":4}
I20260812 06:18:53.680533 14141 maintenance_manager.cc:419] P ac6089a3031e462a943e291bea90f097: Scheduling FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f): perf score=2.188937
I20260812 06:18:53.702600 14037 maintenance_manager.cc:643] P ac6089a3031e462a943e291bea90f097: FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f) complete. Timing: real 0.022s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6478,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:53.703032 14141 maintenance_manager.cc:419] P ac6089a3031e462a943e291bea90f097: Scheduling FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f): perf score=2.188937
I20260812 06:18:53.713414 14037 maintenance_manager.cc:643] P ac6089a3031e462a943e291bea90f097: FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4119,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:53.713819 14141 maintenance_manager.cc:419] P ac6089a3031e462a943e291bea90f097: Scheduling MajorDeltaCompactionOp(81b5643bb80248f98b7be75397c6298f): perf score=1.000000
I20260812 06:18:53.940596 14037 maintenance_manager.cc:643] P ac6089a3031e462a943e291bea90f097: MajorDeltaCompactionOp(81b5643bb80248f98b7be75397c6298f) complete. Timing: real 0.227s	user 0.150s	sys 0.076s Metrics: {"cfile_cache_miss":835,"cfile_cache_miss_bytes":37082269,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":766,"lbm_read_time_us":17242,"lbm_reads_lt_1ms":875,"lbm_write_time_us":42292,"lbm_writes_lt_1ms":843,"mutex_wait_us":27,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":16512,"thread_start_us":78,"threads_started":1,"update_count":4000}
I20260812 06:18:53.941701 14141 maintenance_manager.cc:419] P ac6089a3031e462a943e291bea90f097: Scheduling FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f): perf score=18.063937
I20260812 06:18:53.991343 13591 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.898s	user 1.804s	sys 0.204s
I20260812 06:18:54.006495 14037 maintenance_manager.cc:643] P ac6089a3031e462a943e291bea90f097: FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f) complete. Timing: real 0.065s	user 0.047s	sys 0.016s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":29997,"lbm_writes_lt_1ms":503,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:18:54.007225 14141 maintenance_manager.cc:419] P ac6089a3031e462a943e291bea90f097: Scheduling FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f): perf score=2.188937
I20260812 06:18:54.025492 14037 maintenance_manager.cc:643] P ac6089a3031e462a943e291bea90f097: FlushDeltaMemStoresOp(81b5643bb80248f98b7be75397c6298f) complete. Timing: real 0.018s	user 0.017s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6702,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:54.026048 14141 maintenance_manager.cc:419] P ac6089a3031e462a943e291bea90f097: Scheduling MajorDeltaCompactionOp(81b5643bb80248f98b7be75397c6298f): perf score=1.000000
I20260812 06:18:54.032163 13591 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.040s	user 0.001s	sys 0.000s
I20260812 06:18:54.032799 13591 tablet_server.cc:179] TabletServer@127.13.69.193:0 shutting down...
I20260812 06:18:54.176509 14037 maintenance_manager.cc:643] P ac6089a3031e462a943e291bea90f097: MajorDeltaCompactionOp(81b5643bb80248f98b7be75397c6298f) complete. Timing: real 0.150s	user 0.098s	sys 0.052s Metrics: {"cfile_cache_hit":30,"cfile_cache_hit_bytes":4262390,"cfile_cache_miss":602,"cfile_cache_miss_bytes":24614712,"cfile_init":4,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":667,"lbm_read_time_us":10318,"lbm_reads_lt_1ms":618,"lbm_write_time_us":28358,"lbm_writes_lt_1ms":643,"mutex_wait_us":323,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:18:54.177196 13591 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:54.177431 13591 tablet_replica.cc:333] T 81b5643bb80248f98b7be75397c6298f P ac6089a3031e462a943e291bea90f097: stopping tablet replica
I20260812 06:18:54.177585 13591 raft_consensus.cc:2243] T 81b5643bb80248f98b7be75397c6298f P ac6089a3031e462a943e291bea90f097 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:54.177776 13591 raft_consensus.cc:2272] T 81b5643bb80248f98b7be75397c6298f P ac6089a3031e462a943e291bea90f097 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:54.192473 13591 tablet_server.cc:196] TabletServer@127.13.69.193:0 shutdown complete.
I20260812 06:18:54.228503 13591 master.cc:562] Master@127.13.69.254:36403 shutting down...
I20260812 06:18:54.231799 13591 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 6b442a27b2c3451ca4885740aa4ad2df [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:54.232004 13591 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 6b442a27b2c3451ca4885740aa4ad2df [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:54.232093 13591 tablet_replica.cc:333] T 00000000000000000000000000000000 P 6b442a27b2c3451ca4885740aa4ad2df: stopping tablet replica
I20260812 06:18:54.244807 13591 master.cc:584] Master@127.13.69.254:36403 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5440 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11020 ms total)

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