[==========] 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:46.623016 12581 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.12.73.126:37441
I20260812 06:18:46.624040 12581 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:46.624645 12581 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:46.631256 12586 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:46.631258 12587 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:46.631435 12581 server_base.cc:1061] running on GCE node
W20260812 06:18:46.631592 12589 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:46.632107 12581 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:46.632215 12581 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:46.632259 12581 hybrid_clock.cc:648] HybridClock initialized: now 1786515526632257 us; error 0 us; skew 500 ppm
I20260812 06:18:46.634148 12581 webserver.cc:533] Webserver started at http://127.12.73.126:40817/ using document root <none> and password file <none>
I20260812 06:18:46.634719 12581 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:46.634784 12581 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:46.635031 12581 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:46.636677 12581 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515526611737-12581-0/minicluster-data/master-0-root/instance:
uuid: "80455ff3cd1349a5876f867a39603acc"
format_stamp: "Formatted at 2026-08-12 06:18:46 on dist-test-slave-vq2q"
I20260812 06:18:46.640156 12581 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.005s	sys 0.000s
I20260812 06:18:46.642278 12594 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:46.643309 12581 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:18:46.643414 12581 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515526611737-12581-0/minicluster-data/master-0-root
uuid: "80455ff3cd1349a5876f867a39603acc"
format_stamp: "Formatted at 2026-08-12 06:18:46 on dist-test-slave-vq2q"
I20260812 06:18:46.643514 12581 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515526611737-12581-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515526611737-12581-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515526611737-12581-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:46.656258 12581 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:46.656852 12581 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:46.656996 12581 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:46.665130 12654 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.12.73.126:37441 every 8 connection(s)
I20260812 06:18:46.665139 12581 rpc_server.cc:307] RPC server started. Bound to: 127.12.73.126:37441
I20260812 06:18:46.667464 12655 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:46.672834 12655 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 80455ff3cd1349a5876f867a39603acc: Bootstrap starting.
I20260812 06:18:46.675215 12655 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 80455ff3cd1349a5876f867a39603acc: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:46.676164 12655 log.cc:826] T 00000000000000000000000000000000 P 80455ff3cd1349a5876f867a39603acc: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:46.677865 12655 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 80455ff3cd1349a5876f867a39603acc: No bootstrap required, opened a new log
I20260812 06:18:46.680632 12655 raft_consensus.cc:359] T 00000000000000000000000000000000 P 80455ff3cd1349a5876f867a39603acc [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "80455ff3cd1349a5876f867a39603acc" member_type: VOTER }
I20260812 06:18:46.680804 12655 raft_consensus.cc:385] T 00000000000000000000000000000000 P 80455ff3cd1349a5876f867a39603acc [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:46.680876 12655 raft_consensus.cc:740] T 00000000000000000000000000000000 P 80455ff3cd1349a5876f867a39603acc [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 80455ff3cd1349a5876f867a39603acc, State: Initialized, Role: FOLLOWER
I20260812 06:18:46.681586 12655 consensus_queue.cc:260] T 00000000000000000000000000000000 P 80455ff3cd1349a5876f867a39603acc [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: "80455ff3cd1349a5876f867a39603acc" member_type: VOTER }
I20260812 06:18:46.681735 12655 raft_consensus.cc:399] T 00000000000000000000000000000000 P 80455ff3cd1349a5876f867a39603acc [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:46.681802 12655 raft_consensus.cc:493] T 00000000000000000000000000000000 P 80455ff3cd1349a5876f867a39603acc [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:46.681921 12655 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 80455ff3cd1349a5876f867a39603acc [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:46.682678 12655 raft_consensus.cc:515] T 00000000000000000000000000000000 P 80455ff3cd1349a5876f867a39603acc [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "80455ff3cd1349a5876f867a39603acc" member_type: VOTER }
I20260812 06:18:46.683087 12655 leader_election.cc:304] T 00000000000000000000000000000000 P 80455ff3cd1349a5876f867a39603acc [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: 80455ff3cd1349a5876f867a39603acc; no voters: 
I20260812 06:18:46.683374 12655 leader_election.cc:290] T 00000000000000000000000000000000 P 80455ff3cd1349a5876f867a39603acc [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:46.683480 12659 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 80455ff3cd1349a5876f867a39603acc [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:46.683706 12659 raft_consensus.cc:697] T 00000000000000000000000000000000 P 80455ff3cd1349a5876f867a39603acc [term 1 LEADER]: Becoming Leader. State: Replica: 80455ff3cd1349a5876f867a39603acc, State: Running, Role: LEADER
I20260812 06:18:46.684100 12659 consensus_queue.cc:237] T 00000000000000000000000000000000 P 80455ff3cd1349a5876f867a39603acc [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: "80455ff3cd1349a5876f867a39603acc" member_type: VOTER }
I20260812 06:18:46.684327 12655 sys_catalog.cc:565] T 00000000000000000000000000000000 P 80455ff3cd1349a5876f867a39603acc [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:46.686065 12662 sys_catalog.cc:455] T 00000000000000000000000000000000 P 80455ff3cd1349a5876f867a39603acc [sys.catalog]: SysCatalogTable state changed. Reason: New leader 80455ff3cd1349a5876f867a39603acc. Latest consensus state: current_term: 1 leader_uuid: "80455ff3cd1349a5876f867a39603acc" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "80455ff3cd1349a5876f867a39603acc" member_type: VOTER } }
I20260812 06:18:46.686074 12661 sys_catalog.cc:455] T 00000000000000000000000000000000 P 80455ff3cd1349a5876f867a39603acc [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "80455ff3cd1349a5876f867a39603acc" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "80455ff3cd1349a5876f867a39603acc" member_type: VOTER } }
I20260812 06:18:46.686204 12662 sys_catalog.cc:458] T 00000000000000000000000000000000 P 80455ff3cd1349a5876f867a39603acc [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:46.686206 12661 sys_catalog.cc:458] T 00000000000000000000000000000000 P 80455ff3cd1349a5876f867a39603acc [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:46.686661 12674 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:46.686769 12581 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:46.688884 12674 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:46.693650 12674 catalog_manager.cc:1383] Generated new cluster ID: d9e79c7a7c8d4108b455289c8b9d80af
I20260812 06:18:46.693719 12674 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:46.706292 12674 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:46.707154 12674 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:46.712517 12674 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 80455ff3cd1349a5876f867a39603acc: Generated new TSK 0
I20260812 06:18:46.713124 12674 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:46.719213 12581 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:46.721772 12683 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:46.721947 12581 server_base.cc:1061] running on GCE node
W20260812 06:18:46.721774 12687 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:46.722010 12682 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:46.722311 12581 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:46.722357 12581 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:46.722376 12581 hybrid_clock.cc:648] HybridClock initialized: now 1786515526722376 us; error 0 us; skew 500 ppm
I20260812 06:18:46.723245 12581 webserver.cc:533] Webserver started at http://127.12.73.65:42895/ using document root <none> and password file <none>
I20260812 06:18:46.723409 12581 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:46.723460 12581 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:46.723541 12581 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:46.723906 12581 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515526611737-12581-0/minicluster-data/ts-0-root/instance:
uuid: "98f9f830e10841c289b9a62027e055b3"
format_stamp: "Formatted at 2026-08-12 06:18:46 on dist-test-slave-vq2q"
I20260812 06:18:46.725392 12581 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:46.726441 12694 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:46.726696 12581 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:46.726763 12581 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515526611737-12581-0/minicluster-data/ts-0-root
uuid: "98f9f830e10841c289b9a62027e055b3"
format_stamp: "Formatted at 2026-08-12 06:18:46 on dist-test-slave-vq2q"
I20260812 06:18:46.726832 12581 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515526611737-12581-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515526611737-12581-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515526611737-12581-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:46.736658 12581 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:46.737097 12581 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:46.737651 12581 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:46.738526 12581 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:46.738576 12581 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:46.738623 12581 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:46.738652 12581 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:46.745018 12581 rpc_server.cc:307] RPC server started. Bound to: 127.12.73.65:42285
I20260812 06:18:46.745061 12767 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.12.73.65:42285 every 8 connection(s)
I20260812 06:18:46.758643 12769 heartbeater.cc:344] Connected to a master server at 127.12.73.126:37441
I20260812 06:18:46.758905 12769 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:46.759414 12769 heartbeater.cc:507] Master 127.12.73.126:37441 requested a full tablet report, sending...
I20260812 06:18:46.761297 12612 ts_manager.cc:194] Registered new tserver with Master: 98f9f830e10841c289b9a62027e055b3 (127.12.73.65:42285)
I20260812 06:18:46.761323 12581 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.015703225s
I20260812 06:18:46.762879 12612 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:57952
I20260812 06:18:46.772260 12612 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:57966:
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:46.793381 12728 tablet_service.cc:1511] Processing CreateTablet for tablet d617e18938d74a9eba23292e901b2f64 (DEFAULT_TABLE table=heavy-update-compaction-test [id=65bf575ea3404c69b966c0cf4653fa10]), partition=
I20260812 06:18:46.793920 12728 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet d617e18938d74a9eba23292e901b2f64. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:46.796566 12782 tablet_bootstrap.cc:492] T d617e18938d74a9eba23292e901b2f64 P 98f9f830e10841c289b9a62027e055b3: Bootstrap starting.
I20260812 06:18:46.797585 12782 tablet_bootstrap.cc:654] T d617e18938d74a9eba23292e901b2f64 P 98f9f830e10841c289b9a62027e055b3: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:46.798718 12782 tablet_bootstrap.cc:492] T d617e18938d74a9eba23292e901b2f64 P 98f9f830e10841c289b9a62027e055b3: No bootstrap required, opened a new log
I20260812 06:18:46.798830 12782 ts_tablet_manager.cc:1403] T d617e18938d74a9eba23292e901b2f64 P 98f9f830e10841c289b9a62027e055b3: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:46.799316 12782 raft_consensus.cc:359] T d617e18938d74a9eba23292e901b2f64 P 98f9f830e10841c289b9a62027e055b3 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "98f9f830e10841c289b9a62027e055b3" member_type: VOTER last_known_addr { host: "127.12.73.65" port: 42285 } }
I20260812 06:18:46.799419 12782 raft_consensus.cc:385] T d617e18938d74a9eba23292e901b2f64 P 98f9f830e10841c289b9a62027e055b3 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:46.799450 12782 raft_consensus.cc:740] T d617e18938d74a9eba23292e901b2f64 P 98f9f830e10841c289b9a62027e055b3 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 98f9f830e10841c289b9a62027e055b3, State: Initialized, Role: FOLLOWER
I20260812 06:18:46.799599 12782 consensus_queue.cc:260] T d617e18938d74a9eba23292e901b2f64 P 98f9f830e10841c289b9a62027e055b3 [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: "98f9f830e10841c289b9a62027e055b3" member_type: VOTER last_known_addr { host: "127.12.73.65" port: 42285 } }
I20260812 06:18:46.799700 12782 raft_consensus.cc:399] T d617e18938d74a9eba23292e901b2f64 P 98f9f830e10841c289b9a62027e055b3 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:46.799749 12782 raft_consensus.cc:493] T d617e18938d74a9eba23292e901b2f64 P 98f9f830e10841c289b9a62027e055b3 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:46.799806 12782 raft_consensus.cc:3060] T d617e18938d74a9eba23292e901b2f64 P 98f9f830e10841c289b9a62027e055b3 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:46.800511 12782 raft_consensus.cc:515] T d617e18938d74a9eba23292e901b2f64 P 98f9f830e10841c289b9a62027e055b3 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "98f9f830e10841c289b9a62027e055b3" member_type: VOTER last_known_addr { host: "127.12.73.65" port: 42285 } }
I20260812 06:18:46.800654 12782 leader_election.cc:304] T d617e18938d74a9eba23292e901b2f64 P 98f9f830e10841c289b9a62027e055b3 [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: 98f9f830e10841c289b9a62027e055b3; no voters: 
I20260812 06:18:46.800843 12782 leader_election.cc:290] T d617e18938d74a9eba23292e901b2f64 P 98f9f830e10841c289b9a62027e055b3 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:46.800998 12785 raft_consensus.cc:2804] T d617e18938d74a9eba23292e901b2f64 P 98f9f830e10841c289b9a62027e055b3 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:46.801160 12782 ts_tablet_manager.cc:1434] T d617e18938d74a9eba23292e901b2f64 P 98f9f830e10841c289b9a62027e055b3: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:18:46.801437 12769 heartbeater.cc:499] Master 127.12.73.126:37441 was elected leader, sending a full tablet report...
I20260812 06:18:46.801757 12785 raft_consensus.cc:697] T d617e18938d74a9eba23292e901b2f64 P 98f9f830e10841c289b9a62027e055b3 [term 1 LEADER]: Becoming Leader. State: Replica: 98f9f830e10841c289b9a62027e055b3, State: Running, Role: LEADER
I20260812 06:18:46.801951 12785 consensus_queue.cc:237] T d617e18938d74a9eba23292e901b2f64 P 98f9f830e10841c289b9a62027e055b3 [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: "98f9f830e10841c289b9a62027e055b3" member_type: VOTER last_known_addr { host: "127.12.73.65" port: 42285 } }
I20260812 06:18:46.805020 12610 catalog_manager.cc:5719] T d617e18938d74a9eba23292e901b2f64 P 98f9f830e10841c289b9a62027e055b3 reported cstate change: term changed from 0 to 1, leader changed from <none> to 98f9f830e10841c289b9a62027e055b3 (127.12.73.65). New cstate: current_term: 1 leader_uuid: "98f9f830e10841c289b9a62027e055b3" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "98f9f830e10841c289b9a62027e055b3" member_type: VOTER last_known_addr { host: "127.12.73.65" port: 42285 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:46.869534 12581 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.057s	user 0.027s	sys 0.000s
I20260812 06:18:46.996284 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling FlushMRSOp(d617e18938d74a9eba23292e901b2f64): perf score=15.086190
I20260812 06:18:47.168056 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: FlushMRSOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.171s	user 0.143s	sys 0.020s Metrics: {"bytes_written":13579244,"cfile_init":1,"compiler_manager_pool.queue_time_us":4021,"delete_count":0,"dirs.queue_time_us":48,"dirs.run_cpu_time_us":222,"dirs.run_wall_time_us":1015,"drs_written":1,"lbm_read_time_us":74,"lbm_reads_lt_1ms":4,"lbm_write_time_us":41768,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":687,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"spinlock_wait_cycles":238848,"thread_start_us":109,"threads_started":1,"update_count":1655}
I20260812 06:18:47.169509 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling LogGCOp(d617e18938d74a9eba23292e901b2f64): free 20290830 bytes of WAL
I20260812 06:18:47.169899 12700 log_reader.cc:385] T d617e18938d74a9eba23292e901b2f64: removed 2 log segments from log reader
I20260812 06:18:47.169978 12700 log.cc:1079] T d617e18938d74a9eba23292e901b2f64 P 98f9f830e10841c289b9a62027e055b3: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/d617e18938d74a9eba23292e901b2f64/wal-000000001 (ops 1-6)
I20260812 06:18:47.170047 12700 log.cc:1079] T d617e18938d74a9eba23292e901b2f64 P 98f9f830e10841c289b9a62027e055b3: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/d617e18938d74a9eba23292e901b2f64/wal-000000002 (ops 7-10)
I20260812 06:18:47.174789 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: LogGCOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.005s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:18:47.175249 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling UndoDeltaBlockGCOp(d617e18938d74a9eba23292e901b2f64): 12308958 bytes on disk
I20260812 06:18:47.176007 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: UndoDeltaBlockGCOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":68,"lbm_reads_lt_1ms":4}
I20260812 06:18:47.176463 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64): perf score=4.173312
I20260812 06:18:47.192163 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.016s	user 0.006s	sys 0.008s Metrics: {"bytes_written":5415441,"delete_count":0,"lbm_write_time_us":6193,"lbm_writes_lt_1ms":135,"reinsert_count":0,"update_count":660}
I20260812 06:18:47.192590 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64): perf score=1.000000
I20260812 06:18:47.197780 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.005s	user 0.004s	sys 0.001s Metrics: {"bytes_written":1518077,"delete_count":0,"lbm_write_time_us":1384,"lbm_writes_lt_1ms":40,"reinsert_count":0,"update_count":185}
I20260812 06:18:47.198179 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling MajorDeltaCompactionOp(d617e18938d74a9eba23292e901b2f64): perf score=1.000000
I20260812 06:18:47.342669 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: MajorDeltaCompactionOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.144s	user 0.102s	sys 0.042s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733792,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":914,"lbm_read_time_us":9600,"lbm_reads_lt_1ms":569,"lbm_write_time_us":26886,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":319,"threads_started":5,"update_count":2500}
I20260812 06:18:47.343186 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64): perf score=10.126437
I20260812 06:18:47.383899 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.041s	user 0.012s	sys 0.016s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":12653,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:47.384387 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64): perf score=2.188937
I20260812 06:18:47.394579 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3723,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:47.395174 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling MajorDeltaCompactionOp(d617e18938d74a9eba23292e901b2f64): perf score=1.000000
I20260812 06:18:47.511478 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: MajorDeltaCompactionOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.116s	user 0.084s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631314,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":228,"lbm_read_time_us":7121,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21498,"lbm_writes_lt_1ms":443,"mutex_wait_us":86,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12416,"update_count":2000}
I20260812 06:18:47.511957 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64): perf score=10.126437
I20260812 06:18:47.556362 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.044s	user 0.026s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":21161,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:18:47.556896 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64): perf score=2.188937
I20260812 06:18:47.567466 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.010s	user 0.005s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3550,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:47.568017 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling MajorDeltaCompactionOp(d617e18938d74a9eba23292e901b2f64): perf score=1.000000
I20260812 06:18:47.678836 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: MajorDeltaCompactionOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.111s	user 0.092s	sys 0.018s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":545,"lbm_read_time_us":7319,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20236,"lbm_writes_lt_1ms":443,"mutex_wait_us":254,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:47.679515 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64): perf score=10.126437
I20260812 06:18:47.722968 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.043s	user 0.016s	sys 0.021s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":13694,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:47.723577 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64): perf score=2.188937
I20260812 06:18:47.734123 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3977,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:47.734566 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling MajorDeltaCompactionOp(d617e18938d74a9eba23292e901b2f64): perf score=1.000000
I20260812 06:18:47.881131 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: MajorDeltaCompactionOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.146s	user 0.112s	sys 0.029s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":240,"lbm_read_time_us":10108,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23823,"lbm_writes_lt_1ms":443,"mutex_wait_us":77,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7552,"update_count":2000}
I20260812 06:18:47.881718 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64): perf score=10.126437
I20260812 06:18:47.912868 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.031s	user 0.007s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12383,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:47.913475 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling MajorDeltaCompactionOp(d617e18938d74a9eba23292e901b2f64): perf score=1.000000
I20260812 06:18:48.019748 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: MajorDeltaCompactionOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.106s	user 0.083s	sys 0.020s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16528781,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":2597,"lbm_read_time_us":5972,"lbm_reads_lt_1ms":363,"lbm_write_time_us":19164,"lbm_writes_lt_1ms":343,"mutex_wait_us":2169,"peak_mem_usage":38262756,"reinsert_count":0,"update_count":1500}
I20260812 06:18:48.020295 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64): perf score=10.126437
I20260812 06:18:48.056811 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.036s	user 0.023s	sys 0.007s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":14219,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:48.057431 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64): perf score=2.188937
I20260812 06:18:48.067332 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3563,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:48.067896 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling MajorDeltaCompactionOp(d617e18938d74a9eba23292e901b2f64): perf score=1.000000
I20260812 06:18:48.192200 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: MajorDeltaCompactionOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.124s	user 0.104s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631314,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":294,"lbm_read_time_us":9094,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21171,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:18:48.192795 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64): perf score=10.126437
I20260812 06:18:48.246174 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.053s	user 0.022s	sys 0.019s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":15886,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:48.246824 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64): perf score=2.188937
I20260812 06:18:48.257058 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3895,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:48.257566 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling FlushMRSOp(d617e18938d74a9eba23292e901b2f64): perf score=1.000000
I20260812 06:18:48.287231 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: FlushMRSOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.029s	user 0.025s	sys 0.000s Metrics: {"bytes_written":1152509,"cfile_init":1,"dirs.queue_time_us":101,"dirs.run_cpu_time_us":271,"dirs.run_wall_time_us":1369,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1258,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:48.288115 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling UndoDeltaBlockGCOp(d617e18938d74a9eba23292e901b2f64): 447 bytes on disk
I20260812 06:18:48.288558 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: UndoDeltaBlockGCOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":72,"lbm_reads_lt_1ms":4}
I20260812 06:18:48.289012 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling MajorDeltaCompactionOp(d617e18938d74a9eba23292e901b2f64): perf score=1.000000
I20260812 06:18:48.441298 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: MajorDeltaCompactionOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.152s	user 0.101s	sys 0.038s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631314,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":3271,"dirs.run_cpu_time_us":965,"dirs.run_wall_time_us":5181,"lbm_read_time_us":9477,"lbm_reads_lt_1ms":464,"lbm_write_time_us":22597,"lbm_writes_lt_1ms":443,"mutex_wait_us":2388,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10368,"update_count":2000}
I20260812 06:18:48.441948 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling LogGCOp(d617e18938d74a9eba23292e901b2f64): free 112692383 bytes of WAL
I20260812 06:18:48.442276 12700 log_reader.cc:385] T d617e18938d74a9eba23292e901b2f64: removed 11 log segments from log reader
I20260812 06:18:48.442340 12700 log.cc:1079] T d617e18938d74a9eba23292e901b2f64 P 98f9f830e10841c289b9a62027e055b3: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/d617e18938d74a9eba23292e901b2f64/wal-000000003 (ops 11-15)
I20260812 06:18:48.442385 12700 log.cc:1079] T d617e18938d74a9eba23292e901b2f64 P 98f9f830e10841c289b9a62027e055b3: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/d617e18938d74a9eba23292e901b2f64/wal-000000004 (ops 16-20)
I20260812 06:18:48.442417 12700 log.cc:1079] T d617e18938d74a9eba23292e901b2f64 P 98f9f830e10841c289b9a62027e055b3: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/d617e18938d74a9eba23292e901b2f64/wal-000000005 (ops 21-25)
I20260812 06:18:48.442443 12700 log.cc:1079] T d617e18938d74a9eba23292e901b2f64 P 98f9f830e10841c289b9a62027e055b3: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/d617e18938d74a9eba23292e901b2f64/wal-000000006 (ops 26-30)
I20260812 06:18:48.442474 12700 log.cc:1079] T d617e18938d74a9eba23292e901b2f64 P 98f9f830e10841c289b9a62027e055b3: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/d617e18938d74a9eba23292e901b2f64/wal-000000007 (ops 31-35)
I20260812 06:18:48.442497 12700 log.cc:1079] T d617e18938d74a9eba23292e901b2f64 P 98f9f830e10841c289b9a62027e055b3: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/d617e18938d74a9eba23292e901b2f64/wal-000000008 (ops 36-40)
I20260812 06:18:48.442533 12700 log.cc:1079] T d617e18938d74a9eba23292e901b2f64 P 98f9f830e10841c289b9a62027e055b3: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/d617e18938d74a9eba23292e901b2f64/wal-000000009 (ops 41-45)
I20260812 06:18:48.442564 12700 log.cc:1079] T d617e18938d74a9eba23292e901b2f64 P 98f9f830e10841c289b9a62027e055b3: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/d617e18938d74a9eba23292e901b2f64/wal-000000010 (ops 46-50)
I20260812 06:18:48.442593 12700 log.cc:1079] T d617e18938d74a9eba23292e901b2f64 P 98f9f830e10841c289b9a62027e055b3: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/d617e18938d74a9eba23292e901b2f64/wal-000000011 (ops 51-55)
I20260812 06:18:48.442622 12700 log.cc:1079] T d617e18938d74a9eba23292e901b2f64 P 98f9f830e10841c289b9a62027e055b3: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/d617e18938d74a9eba23292e901b2f64/wal-000000012 (ops 56-60)
I20260812 06:18:48.442652 12700 log.cc:1079] T d617e18938d74a9eba23292e901b2f64 P 98f9f830e10841c289b9a62027e055b3: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/d617e18938d74a9eba23292e901b2f64/wal-000000013 (ops 61-65)
I20260812 06:18:48.463667 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: LogGCOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.021s	user 0.000s	sys 0.019s Metrics: {}
I20260812 06:18:48.464155 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64): perf score=15.087375
I20260812 06:18:48.510612 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.046s	user 0.033s	sys 0.011s Metrics: {"bytes_written":16820144,"delete_count":0,"lbm_write_time_us":19707,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:18:48.511168 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64): perf score=2.188937
I20260812 06:18:48.525658 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.014s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3708,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:48.526192 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64): perf score=2.188937
I20260812 06:18:48.546792 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.020s	user 0.008s	sys 0.011s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4770,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:48.547451 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling MajorDeltaCompactionOp(d617e18938d74a9eba23292e901b2f64): perf score=1.000000
I20260812 06:18:48.755769 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: MajorDeltaCompactionOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.208s	user 0.140s	sys 0.060s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28836243,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":126,"lbm_read_time_us":14734,"lbm_reads_lt_1ms":673,"lbm_write_time_us":34448,"lbm_writes_lt_1ms":643,"mutex_wait_us":22,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":17280,"update_count":3000}
I20260812 06:18:48.756412 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64): perf score=14.095187
I20260812 06:18:48.809985 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.053s	user 0.021s	sys 0.027s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":16500,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:48.810602 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64): perf score=2.188937
I20260812 06:18:48.825961 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.015s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5778,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:48.826495 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling MajorDeltaCompactionOp(d617e18938d74a9eba23292e901b2f64): perf score=1.000000
I20260812 06:18:49.003314 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: MajorDeltaCompactionOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.177s	user 0.125s	sys 0.051s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":587,"lbm_read_time_us":12978,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28622,"lbm_writes_lt_1ms":543,"mutex_wait_us":306,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":2500}
I20260812 06:18:49.003883 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64): perf score=11.118625
I20260812 06:18:49.032866 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.029s	user 0.014s	sys 0.012s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":12256,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:49.033444 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64): perf score=2.188937
I20260812 06:18:49.044227 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3488,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:49.045401 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling MajorDeltaCompactionOp(d617e18938d74a9eba23292e901b2f64): perf score=1.000000
I20260812 06:18:49.172695 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: MajorDeltaCompactionOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.127s	user 0.083s	sys 0.041s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631303,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":141,"lbm_read_time_us":9671,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21609,"lbm_writes_lt_1ms":443,"mutex_wait_us":46,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6528,"update_count":2000}
I20260812 06:18:49.173302 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64): perf score=10.126437
I20260812 06:18:49.215342 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.042s	user 0.015s	sys 0.013s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":12651,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:49.215938 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64): perf score=2.188937
I20260812 06:18:49.226329 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3575,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:49.227003 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling MajorDeltaCompactionOp(d617e18938d74a9eba23292e901b2f64): perf score=1.000000
I20260812 06:18:49.342985 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: MajorDeltaCompactionOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.116s	user 0.085s	sys 0.030s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":266,"lbm_read_time_us":7831,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21168,"lbm_writes_lt_1ms":443,"mutex_wait_us":48,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8960,"update_count":2000}
I20260812 06:18:49.343626 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64): perf score=10.126437
I20260812 06:18:49.388772 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.045s	user 0.031s	sys 0.008s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":19044,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:49.389374 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64): perf score=2.188937
I20260812 06:18:49.399060 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3486,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:49.399520 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling MajorDeltaCompactionOp(d617e18938d74a9eba23292e901b2f64): perf score=1.000000
I20260812 06:18:49.521852 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: MajorDeltaCompactionOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.122s	user 0.098s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631315,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":230,"lbm_read_time_us":8430,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23040,"lbm_writes_lt_1ms":443,"mutex_wait_us":50,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11392,"update_count":2000}
I20260812 06:18:49.522555 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64): perf score=10.126437
I20260812 06:18:49.570164 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.047s	user 0.019s	sys 0.027s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14848,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:49.570791 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64): perf score=2.188937
I20260812 06:18:49.586664 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.016s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5944,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:49.587185 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling MajorDeltaCompactionOp(d617e18938d74a9eba23292e901b2f64): perf score=1.000000
I20260812 06:18:49.723691 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: MajorDeltaCompactionOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.136s	user 0.094s	sys 0.043s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":177,"lbm_read_time_us":10380,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21247,"lbm_writes_lt_1ms":443,"mutex_wait_us":33,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14080,"update_count":2000}
I20260812 06:18:49.724251 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64): perf score=10.126437
I20260812 06:18:49.764384 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.040s	user 0.024s	sys 0.013s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17743,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"spinlock_wait_cycles":20224,"update_count":1500}
I20260812 06:18:49.764946 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64): perf score=2.188937
I20260812 06:18:49.780968 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.016s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5669,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:49.783349 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling FlushMRSOp(d617e18938d74a9eba23292e901b2f64): perf score=1.000000
I20260812 06:18:49.813933 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: FlushMRSOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.030s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":61,"dirs.run_cpu_time_us":221,"dirs.run_wall_time_us":1293,"drs_written":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1835,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:49.814896 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling LogGCOp(d617e18938d74a9eba23292e901b2f64): free 124710298 bytes of WAL
I20260812 06:18:49.815152 12700 log_reader.cc:385] T d617e18938d74a9eba23292e901b2f64: removed 12 log segments from log reader
I20260812 06:18:49.815218 12700 log.cc:1079] T d617e18938d74a9eba23292e901b2f64 P 98f9f830e10841c289b9a62027e055b3: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/d617e18938d74a9eba23292e901b2f64/wal-000000014 (ops 66-70)
I20260812 06:18:49.815258 12700 log.cc:1079] T d617e18938d74a9eba23292e901b2f64 P 98f9f830e10841c289b9a62027e055b3: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/d617e18938d74a9eba23292e901b2f64/wal-000000015 (ops 71-75)
I20260812 06:18:49.815287 12700 log.cc:1079] T d617e18938d74a9eba23292e901b2f64 P 98f9f830e10841c289b9a62027e055b3: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/d617e18938d74a9eba23292e901b2f64/wal-000000016 (ops 76-80)
I20260812 06:18:49.815318 12700 log.cc:1079] T d617e18938d74a9eba23292e901b2f64 P 98f9f830e10841c289b9a62027e055b3: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/d617e18938d74a9eba23292e901b2f64/wal-000000017 (ops 81-85)
I20260812 06:18:49.815351 12700 log.cc:1079] T d617e18938d74a9eba23292e901b2f64 P 98f9f830e10841c289b9a62027e055b3: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/d617e18938d74a9eba23292e901b2f64/wal-000000018 (ops 86-90)
I20260812 06:18:49.815377 12700 log.cc:1079] T d617e18938d74a9eba23292e901b2f64 P 98f9f830e10841c289b9a62027e055b3: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/d617e18938d74a9eba23292e901b2f64/wal-000000019 (ops 91-95)
I20260812 06:18:49.815404 12700 log.cc:1079] T d617e18938d74a9eba23292e901b2f64 P 98f9f830e10841c289b9a62027e055b3: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/d617e18938d74a9eba23292e901b2f64/wal-000000020 (ops 96-100)
I20260812 06:18:49.815429 12700 log.cc:1079] T d617e18938d74a9eba23292e901b2f64 P 98f9f830e10841c289b9a62027e055b3: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/d617e18938d74a9eba23292e901b2f64/wal-000000021 (ops 101-105)
I20260812 06:18:49.815459 12700 log.cc:1079] T d617e18938d74a9eba23292e901b2f64 P 98f9f830e10841c289b9a62027e055b3: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/d617e18938d74a9eba23292e901b2f64/wal-000000022 (ops 106-110)
I20260812 06:18:49.815501 12700 log.cc:1079] T d617e18938d74a9eba23292e901b2f64 P 98f9f830e10841c289b9a62027e055b3: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/d617e18938d74a9eba23292e901b2f64/wal-000000023 (ops 111-115)
I20260812 06:18:49.815531 12700 log.cc:1079] T d617e18938d74a9eba23292e901b2f64 P 98f9f830e10841c289b9a62027e055b3: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/d617e18938d74a9eba23292e901b2f64/wal-000000024 (ops 116-120)
I20260812 06:18:49.815555 12700 log.cc:1079] T d617e18938d74a9eba23292e901b2f64 P 98f9f830e10841c289b9a62027e055b3: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/d617e18938d74a9eba23292e901b2f64/wal-000000025 (ops 121-125)
I20260812 06:18:49.838239 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: LogGCOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.023s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:18:49.838680 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64): perf score=2.188937
I20260812 06:18:49.860682 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.022s	user 0.009s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4014,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:49.861209 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64): perf score=2.188937
I20260812 06:18:49.876366 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5828,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:49.876945 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling UndoDeltaBlockGCOp(d617e18938d74a9eba23292e901b2f64): 482 bytes on disk
I20260812 06:18:49.877485 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: UndoDeltaBlockGCOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":73,"lbm_reads_lt_1ms":4}
I20260812 06:18:49.878023 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling MajorDeltaCompactionOp(d617e18938d74a9eba23292e901b2f64): perf score=1.000000
I20260812 06:18:50.067391 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: MajorDeltaCompactionOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.189s	user 0.136s	sys 0.046s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836374,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":585,"lbm_read_time_us":13743,"lbm_reads_lt_1ms":674,"lbm_write_time_us":29700,"lbm_writes_lt_1ms":643,"mutex_wait_us":25,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":41088,"thread_start_us":78,"threads_started":1,"update_count":3000}
I20260812 06:18:50.068545 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64): perf score=14.095187
I20260812 06:18:50.134187 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.065s	user 0.030s	sys 0.028s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22295,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:50.134701 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64): perf score=2.188937
I20260812 06:18:50.145412 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.011s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4064,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:50.145944 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling MajorDeltaCompactionOp(d617e18938d74a9eba23292e901b2f64): perf score=1.000000
I20260812 06:18:50.299182 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: MajorDeltaCompactionOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.153s	user 0.113s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":178,"lbm_read_time_us":11689,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25037,"lbm_writes_lt_1ms":543,"mutex_wait_us":63,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:50.299839 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64): perf score=10.126437
I20260812 06:18:50.342922 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.043s	user 0.029s	sys 0.011s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":16624,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:50.343564 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64): perf score=3.181125
I20260812 06:18:50.366205 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.022s	user 0.013s	sys 0.001s Metrics: {"bytes_written":4471879,"delete_count":0,"lbm_write_time_us":5704,"lbm_writes_lt_1ms":112,"reinsert_count":0,"update_count":545}
I20260812 06:18:50.366729 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64): perf score=2.188937
I20260812 06:18:50.381909 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.015s	user 0.006s	sys 0.008s Metrics: {"bytes_written":3733434,"delete_count":0,"lbm_write_time_us":3191,"lbm_writes_lt_1ms":94,"reinsert_count":0,"update_count":455}
I20260812 06:18:50.382426 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling MajorDeltaCompactionOp(d617e18938d74a9eba23292e901b2f64): perf score=1.000000
I20260812 06:18:50.554098 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: MajorDeltaCompactionOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.171s	user 0.108s	sys 0.052s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733840,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":568,"lbm_read_time_us":11026,"lbm_reads_lt_1ms":573,"lbm_write_time_us":26947,"lbm_writes_lt_1ms":543,"mutex_wait_us":35,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:50.554651 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64): perf score=14.095187
I20260812 06:18:50.606735 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.052s	user 0.038s	sys 0.012s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22443,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:50.607268 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64): perf score=2.188937
I20260812 06:18:50.617445 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3686,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:50.618144 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling MajorDeltaCompactionOp(d617e18938d74a9eba23292e901b2f64): perf score=1.000000
I20260812 06:18:50.792985 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: MajorDeltaCompactionOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.175s	user 0.117s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":102,"lbm_read_time_us":10639,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26426,"lbm_writes_lt_1ms":543,"mutex_wait_us":37,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":60928,"update_count":2500}
I20260812 06:18:50.793627 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64): perf score=14.095187
I20260812 06:18:50.841332 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.048s	user 0.043s	sys 0.003s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20117,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:50.841864 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64): perf score=2.188937
I20260812 06:18:50.852814 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.011s	user 0.008s	sys 0.000s 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:50.853483 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling MajorDeltaCompactionOp(d617e18938d74a9eba23292e901b2f64): perf score=1.000000
I20260812 06:18:50.995795 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: MajorDeltaCompactionOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.142s	user 0.124s	sys 0.016s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":268,"lbm_read_time_us":9296,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27880,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:18:50.996472 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64): perf score=11.118625
I20260812 06:18:51.027242 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.031s	user 0.009s	sys 0.020s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":13821,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:18:51.027783 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64): perf score=2.188937
I20260812 06:18:51.055540 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.028s	user 0.006s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5928,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:51.056164 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64): perf score=2.188937
I20260812 06:18:51.066282 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.010s	user 0.008s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3630,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:51.066973 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling MajorDeltaCompactionOp(d617e18938d74a9eba23292e901b2f64): perf score=1.000000
I20260812 06:18:51.222559 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: MajorDeltaCompactionOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.155s	user 0.124s	sys 0.021s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733834,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":561,"lbm_read_time_us":11261,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29507,"lbm_writes_lt_1ms":543,"mutex_wait_us":25,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":2500}
I20260812 06:18:51.223160 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64): perf score=14.095187
I20260812 06:18:51.277699 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.054s	user 0.035s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24068,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:51.278299 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64): perf score=2.188937
I20260812 06:18:51.289845 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4353,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:51.290374 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling FlushMRSOp(d617e18938d74a9eba23292e901b2f64): perf score=1.000000
I20260812 06:18:51.322587 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: FlushMRSOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.032s	user 0.026s	sys 0.004s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":58,"dirs.run_cpu_time_us":207,"dirs.run_wall_time_us":1365,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1918,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:18:51.323275 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling LogGCOp(d617e18938d74a9eba23292e901b2f64): free 129320769 bytes of WAL
I20260812 06:18:51.323496 12700 log_reader.cc:385] T d617e18938d74a9eba23292e901b2f64: removed 13 log segments from log reader
I20260812 06:18:51.323544 12700 log.cc:1079] T d617e18938d74a9eba23292e901b2f64 P 98f9f830e10841c289b9a62027e055b3: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/d617e18938d74a9eba23292e901b2f64/wal-000000026 (ops 126-130)
I20260812 06:18:51.323573 12700 log.cc:1079] T d617e18938d74a9eba23292e901b2f64 P 98f9f830e10841c289b9a62027e055b3: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/d617e18938d74a9eba23292e901b2f64/wal-000000027 (ops 131-135)
I20260812 06:18:51.323604 12700 log.cc:1079] T d617e18938d74a9eba23292e901b2f64 P 98f9f830e10841c289b9a62027e055b3: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/d617e18938d74a9eba23292e901b2f64/wal-000000028 (ops 136-140)
I20260812 06:18:51.323637 12700 log.cc:1079] T d617e18938d74a9eba23292e901b2f64 P 98f9f830e10841c289b9a62027e055b3: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/d617e18938d74a9eba23292e901b2f64/wal-000000029 (ops 141-144)
I20260812 06:18:51.323666 12700 log.cc:1079] T d617e18938d74a9eba23292e901b2f64 P 98f9f830e10841c289b9a62027e055b3: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/d617e18938d74a9eba23292e901b2f64/wal-000000030 (ops 145-149)
I20260812 06:18:51.323700 12700 log.cc:1079] T d617e18938d74a9eba23292e901b2f64 P 98f9f830e10841c289b9a62027e055b3: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/d617e18938d74a9eba23292e901b2f64/wal-000000031 (ops 150-154)
I20260812 06:18:51.323731 12700 log.cc:1079] T d617e18938d74a9eba23292e901b2f64 P 98f9f830e10841c289b9a62027e055b3: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/d617e18938d74a9eba23292e901b2f64/wal-000000032 (ops 155-159)
I20260812 06:18:51.323761 12700 log.cc:1079] T d617e18938d74a9eba23292e901b2f64 P 98f9f830e10841c289b9a62027e055b3: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/d617e18938d74a9eba23292e901b2f64/wal-000000033 (ops 160-164)
I20260812 06:18:51.323792 12700 log.cc:1079] T d617e18938d74a9eba23292e901b2f64 P 98f9f830e10841c289b9a62027e055b3: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/d617e18938d74a9eba23292e901b2f64/wal-000000034 (ops 165-168)
I20260812 06:18:51.323823 12700 log.cc:1079] T d617e18938d74a9eba23292e901b2f64 P 98f9f830e10841c289b9a62027e055b3: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/d617e18938d74a9eba23292e901b2f64/wal-000000035 (ops 169-173)
I20260812 06:18:51.323853 12700 log.cc:1079] T d617e18938d74a9eba23292e901b2f64 P 98f9f830e10841c289b9a62027e055b3: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/d617e18938d74a9eba23292e901b2f64/wal-000000036 (ops 174-178)
I20260812 06:18:51.323884 12700 log.cc:1079] T d617e18938d74a9eba23292e901b2f64 P 98f9f830e10841c289b9a62027e055b3: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/d617e18938d74a9eba23292e901b2f64/wal-000000037 (ops 179-183)
I20260812 06:18:51.323915 12700 log.cc:1079] T d617e18938d74a9eba23292e901b2f64 P 98f9f830e10841c289b9a62027e055b3: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/d617e18938d74a9eba23292e901b2f64/wal-000000038 (ops 184-188)
I20260812 06:18:51.347194 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: LogGCOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.024s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:18:51.347608 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64): perf score=4.173312
I20260812 06:18:51.362048 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.014s	user 0.013s	sys 0.000s Metrics: {"bytes_written":5948752,"delete_count":0,"lbm_write_time_us":5890,"lbm_writes_lt_1ms":148,"reinsert_count":0,"update_count":725}
I20260812 06:18:51.362494 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling LogGCOp(d617e18938d74a9eba23292e901b2f64): free 11564893 bytes of WAL
I20260812 06:18:51.362700 12700 log_reader.cc:385] T d617e18938d74a9eba23292e901b2f64: removed 1 log segments from log reader
I20260812 06:18:51.362746 12700 log.cc:1079] T d617e18938d74a9eba23292e901b2f64 P 98f9f830e10841c289b9a62027e055b3: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/d617e18938d74a9eba23292e901b2f64/wal-000000039 (ops 189-192)
I20260812 06:18:51.364549 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: LogGCOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:18:51.364885 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64): perf score=1.196750
I20260812 06:18:51.386945 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.022s	user 0.008s	sys 0.007s Metrics: {"bytes_written":2256529,"delete_count":0,"lbm_write_time_us":3702,"lbm_writes_lt_1ms":58,"reinsert_count":0,"update_count":275}
I20260812 06:18:51.387599 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling UndoDeltaBlockGCOp(d617e18938d74a9eba23292e901b2f64): 493 bytes on disk
I20260812 06:18:51.388036 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: UndoDeltaBlockGCOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4}
I20260812 06:18:51.388584 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling MajorDeltaCompactionOp(d617e18938d74a9eba23292e901b2f64): perf score=1.000000
I20260812 06:18:51.564146 12581 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.695s	user 1.727s	sys 0.136s
I20260812 06:18:51.600956 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: MajorDeltaCompactionOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.212s	user 0.129s	sys 0.080s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32938741,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":14908,"lbm_reads_lt_1ms":762,"lbm_write_time_us":36545,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"update_count":3500}
I20260812 06:18:51.601512 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64): perf score=14.095187
I20260812 06:18:51.640729 12581 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.076s	user 0.001s	sys 0.000s
I20260812 06:18:51.641388 12581 tablet_server.cc:179] TabletServer@127.12.73.65:0 shutting down...
I20260812 06:18:51.641993 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: FlushDeltaMemStoresOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.040s	user 0.024s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":16410,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:51.642524 12771 maintenance_manager.cc:419] P 98f9f830e10841c289b9a62027e055b3: Scheduling MajorDeltaCompactionOp(d617e18938d74a9eba23292e901b2f64): perf score=1.000000
I20260812 06:18:51.754294 12700 maintenance_manager.cc:643] P 98f9f830e10841c289b9a62027e055b3: MajorDeltaCompactionOp(d617e18938d74a9eba23292e901b2f64) complete. Timing: real 0.112s	user 0.091s	sys 0.020s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20631192,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":414,"lbm_read_time_us":10892,"lbm_reads_1-10_ms":2,"lbm_reads_lt_1ms":465,"lbm_write_time_us":19704,"lbm_writes_lt_1ms":443,"mutex_wait_us":95,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:51.755051 12581 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:51.755481 12581 tablet_replica.cc:333] T d617e18938d74a9eba23292e901b2f64 P 98f9f830e10841c289b9a62027e055b3: stopping tablet replica
I20260812 06:18:51.755728 12581 raft_consensus.cc:2243] T d617e18938d74a9eba23292e901b2f64 P 98f9f830e10841c289b9a62027e055b3 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:51.755965 12581 raft_consensus.cc:2272] T d617e18938d74a9eba23292e901b2f64 P 98f9f830e10841c289b9a62027e055b3 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:51.789800 12581 tablet_server.cc:196] TabletServer@127.12.73.65:0 shutdown complete.
I20260812 06:18:51.794725 12581 master.cc:562] Master@127.12.73.126:37441 shutting down...
I20260812 06:18:51.797793 12581 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 80455ff3cd1349a5876f867a39603acc [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:51.797971 12581 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 80455ff3cd1349a5876f867a39603acc [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:51.798048 12581 tablet_replica.cc:333] T 00000000000000000000000000000000 P 80455ff3cd1349a5876f867a39603acc: stopping tablet replica
I20260812 06:18:51.810243 12581 master.cc:584] Master@127.12.73.126:37441 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5258 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:51.881071 12581 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.12.73.126:39469
I20260812 06:18:51.881485 12581 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:51.883561 12810 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:51.883596 12809 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:51.883671 12812 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:51.883878 12581 server_base.cc:1061] running on GCE node
I20260812 06:18:51.884022 12581 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:51.884059 12581 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:51.884078 12581 hybrid_clock.cc:648] HybridClock initialized: now 1786515531884078 us; error 0 us; skew 500 ppm
I20260812 06:18:51.884925 12581 webserver.cc:533] Webserver started at http://127.12.73.126:45473/ using document root <none> and password file <none>
I20260812 06:18:51.885088 12581 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:51.885138 12581 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:51.885267 12581 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:51.885638 12581 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515526611737-12581-0/minicluster-data/master-0-root/instance:
uuid: "ac18bf16aef541879912ce9ab382e2e5"
format_stamp: "Formatted at 2026-08-12 06:18:51 on dist-test-slave-vq2q"
I20260812 06:18:51.887056 12581 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:51.888520 12817 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:51.888793 12581 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:51.888891 12581 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515526611737-12581-0/minicluster-data/master-0-root
uuid: "ac18bf16aef541879912ce9ab382e2e5"
format_stamp: "Formatted at 2026-08-12 06:18:51 on dist-test-slave-vq2q"
I20260812 06:18:51.888974 12581 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515526611737-12581-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515526611737-12581-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515526611737-12581-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:51.896186 12581 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:51.896533 12581 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:51.900550 12581 rpc_server.cc:307] RPC server started. Bound to: 127.12.73.126:39469
I20260812 06:18:51.914069 12882 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.12.73.126:39469 every 8 connection(s)
I20260812 06:18:51.914592 12883 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:51.916450 12883 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P ac18bf16aef541879912ce9ab382e2e5: Bootstrap starting.
I20260812 06:18:51.917290 12883 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P ac18bf16aef541879912ce9ab382e2e5: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:51.918366 12883 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P ac18bf16aef541879912ce9ab382e2e5: No bootstrap required, opened a new log
I20260812 06:18:51.918772 12883 raft_consensus.cc:359] T 00000000000000000000000000000000 P ac18bf16aef541879912ce9ab382e2e5 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ac18bf16aef541879912ce9ab382e2e5" member_type: VOTER }
I20260812 06:18:51.918892 12883 raft_consensus.cc:385] T 00000000000000000000000000000000 P ac18bf16aef541879912ce9ab382e2e5 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:51.918926 12883 raft_consensus.cc:740] T 00000000000000000000000000000000 P ac18bf16aef541879912ce9ab382e2e5 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: ac18bf16aef541879912ce9ab382e2e5, State: Initialized, Role: FOLLOWER
I20260812 06:18:51.919072 12883 consensus_queue.cc:260] T 00000000000000000000000000000000 P ac18bf16aef541879912ce9ab382e2e5 [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: "ac18bf16aef541879912ce9ab382e2e5" member_type: VOTER }
I20260812 06:18:51.919147 12883 raft_consensus.cc:399] T 00000000000000000000000000000000 P ac18bf16aef541879912ce9ab382e2e5 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:51.919186 12883 raft_consensus.cc:493] T 00000000000000000000000000000000 P ac18bf16aef541879912ce9ab382e2e5 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:51.919236 12883 raft_consensus.cc:3060] T 00000000000000000000000000000000 P ac18bf16aef541879912ce9ab382e2e5 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:51.919927 12883 raft_consensus.cc:515] T 00000000000000000000000000000000 P ac18bf16aef541879912ce9ab382e2e5 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ac18bf16aef541879912ce9ab382e2e5" member_type: VOTER }
I20260812 06:18:51.920063 12883 leader_election.cc:304] T 00000000000000000000000000000000 P ac18bf16aef541879912ce9ab382e2e5 [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: ac18bf16aef541879912ce9ab382e2e5; no voters: 
I20260812 06:18:51.920252 12883 leader_election.cc:290] T 00000000000000000000000000000000 P ac18bf16aef541879912ce9ab382e2e5 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:51.920352 12888 raft_consensus.cc:2804] T 00000000000000000000000000000000 P ac18bf16aef541879912ce9ab382e2e5 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:51.920557 12888 raft_consensus.cc:697] T 00000000000000000000000000000000 P ac18bf16aef541879912ce9ab382e2e5 [term 1 LEADER]: Becoming Leader. State: Replica: ac18bf16aef541879912ce9ab382e2e5, State: Running, Role: LEADER
I20260812 06:18:51.920688 12883 sys_catalog.cc:565] T 00000000000000000000000000000000 P ac18bf16aef541879912ce9ab382e2e5 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:51.920696 12888 consensus_queue.cc:237] T 00000000000000000000000000000000 P ac18bf16aef541879912ce9ab382e2e5 [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: "ac18bf16aef541879912ce9ab382e2e5" member_type: VOTER }
I20260812 06:18:51.921211 12889 sys_catalog.cc:455] T 00000000000000000000000000000000 P ac18bf16aef541879912ce9ab382e2e5 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "ac18bf16aef541879912ce9ab382e2e5" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ac18bf16aef541879912ce9ab382e2e5" member_type: VOTER } }
I20260812 06:18:51.921249 12890 sys_catalog.cc:455] T 00000000000000000000000000000000 P ac18bf16aef541879912ce9ab382e2e5 [sys.catalog]: SysCatalogTable state changed. Reason: New leader ac18bf16aef541879912ce9ab382e2e5. Latest consensus state: current_term: 1 leader_uuid: "ac18bf16aef541879912ce9ab382e2e5" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ac18bf16aef541879912ce9ab382e2e5" member_type: VOTER } }
I20260812 06:18:51.921324 12889 sys_catalog.cc:458] T 00000000000000000000000000000000 P ac18bf16aef541879912ce9ab382e2e5 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:51.921336 12890 sys_catalog.cc:458] T 00000000000000000000000000000000 P ac18bf16aef541879912ce9ab382e2e5 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:51.921597 12896 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:51.922439 12896 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:51.922608 12581 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:51.924237 12896 catalog_manager.cc:1383] Generated new cluster ID: 0e8082216a434b24884b0a43cf118b2a
I20260812 06:18:51.924283 12896 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:51.949558 12896 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:51.950155 12896 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:51.959146 12896 catalog_manager.cc:6092] T 00000000000000000000000000000000 P ac18bf16aef541879912ce9ab382e2e5: Generated new TSK 0
I20260812 06:18:51.959334 12896 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:51.991446 12581 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:51.993748 12910 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:51.993738 12911 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:51.993866 12913 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:51.994061 12581 server_base.cc:1061] running on GCE node
I20260812 06:18:51.994336 12581 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:51.994385 12581 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:51.994398 12581 hybrid_clock.cc:648] HybridClock initialized: now 1786515531994398 us; error 0 us; skew 500 ppm
I20260812 06:18:51.995250 12581 webserver.cc:533] Webserver started at http://127.12.73.65:42319/ using document root <none> and password file <none>
I20260812 06:18:51.995420 12581 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:51.995465 12581 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:51.995538 12581 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:51.995929 12581 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515526611737-12581-0/minicluster-data/ts-0-root/instance:
uuid: "3b31af3936534a8a96e91cd5f2444602"
format_stamp: "Formatted at 2026-08-12 06:18:51 on dist-test-slave-vq2q"
I20260812 06:18:51.997416 12581 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:51.998354 12919 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:51.998581 12581 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:51.998651 12581 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515526611737-12581-0/minicluster-data/ts-0-root
uuid: "3b31af3936534a8a96e91cd5f2444602"
format_stamp: "Formatted at 2026-08-12 06:18:51 on dist-test-slave-vq2q"
I20260812 06:18:51.998721 12581 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515526611737-12581-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515526611737-12581-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515526611737-12581-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:52.014204 12581 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:52.014600 12581 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:52.014935 12581 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:52.015455 12581 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:52.015497 12581 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:52.015538 12581 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:52.015566 12581 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:52.020704 12581 rpc_server.cc:307] RPC server started. Bound to: 127.12.73.65:42915
I20260812 06:18:52.020730 12991 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.12.73.65:42915 every 8 connection(s)
I20260812 06:18:52.029038 12992 heartbeater.cc:344] Connected to a master server at 127.12.73.126:39469
I20260812 06:18:52.029150 12992 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:52.029414 12992 heartbeater.cc:507] Master 127.12.73.126:39469 requested a full tablet report, sending...
I20260812 06:18:52.030138 12840 ts_manager.cc:194] Registered new tserver with Master: 3b31af3936534a8a96e91cd5f2444602 (127.12.73.65:42915)
I20260812 06:18:52.030185 12581 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.008969482s
I20260812 06:18:52.031209 12840 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:51472
I20260812 06:18:52.037729 12840 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:51482:
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:52.046857 12948 tablet_service.cc:1511] Processing CreateTablet for tablet 75aa4f4740e04c2982f83579df3c8893 (DEFAULT_TABLE table=heavy-update-compaction-test [id=881d302a39ff416cade962c8075e87da]), partition=
I20260812 06:18:52.047124 12948 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 75aa4f4740e04c2982f83579df3c8893. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:52.049326 13008 tablet_bootstrap.cc:492] T 75aa4f4740e04c2982f83579df3c8893 P 3b31af3936534a8a96e91cd5f2444602: Bootstrap starting.
I20260812 06:18:52.050429 13008 tablet_bootstrap.cc:654] T 75aa4f4740e04c2982f83579df3c8893 P 3b31af3936534a8a96e91cd5f2444602: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:52.051630 13008 tablet_bootstrap.cc:492] T 75aa4f4740e04c2982f83579df3c8893 P 3b31af3936534a8a96e91cd5f2444602: No bootstrap required, opened a new log
I20260812 06:18:52.051723 13008 ts_tablet_manager.cc:1403] T 75aa4f4740e04c2982f83579df3c8893 P 3b31af3936534a8a96e91cd5f2444602: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:52.052245 13008 raft_consensus.cc:359] T 75aa4f4740e04c2982f83579df3c8893 P 3b31af3936534a8a96e91cd5f2444602 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3b31af3936534a8a96e91cd5f2444602" member_type: VOTER last_known_addr { host: "127.12.73.65" port: 42915 } }
I20260812 06:18:52.052362 13008 raft_consensus.cc:385] T 75aa4f4740e04c2982f83579df3c8893 P 3b31af3936534a8a96e91cd5f2444602 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:52.052402 13008 raft_consensus.cc:740] T 75aa4f4740e04c2982f83579df3c8893 P 3b31af3936534a8a96e91cd5f2444602 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 3b31af3936534a8a96e91cd5f2444602, State: Initialized, Role: FOLLOWER
I20260812 06:18:52.052546 13008 consensus_queue.cc:260] T 75aa4f4740e04c2982f83579df3c8893 P 3b31af3936534a8a96e91cd5f2444602 [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: "3b31af3936534a8a96e91cd5f2444602" member_type: VOTER last_known_addr { host: "127.12.73.65" port: 42915 } }
I20260812 06:18:52.052632 13008 raft_consensus.cc:399] T 75aa4f4740e04c2982f83579df3c8893 P 3b31af3936534a8a96e91cd5f2444602 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:52.052671 13008 raft_consensus.cc:493] T 75aa4f4740e04c2982f83579df3c8893 P 3b31af3936534a8a96e91cd5f2444602 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:52.052721 13008 raft_consensus.cc:3060] T 75aa4f4740e04c2982f83579df3c8893 P 3b31af3936534a8a96e91cd5f2444602 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:52.053689 13008 raft_consensus.cc:515] T 75aa4f4740e04c2982f83579df3c8893 P 3b31af3936534a8a96e91cd5f2444602 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3b31af3936534a8a96e91cd5f2444602" member_type: VOTER last_known_addr { host: "127.12.73.65" port: 42915 } }
I20260812 06:18:52.053838 13008 leader_election.cc:304] T 75aa4f4740e04c2982f83579df3c8893 P 3b31af3936534a8a96e91cd5f2444602 [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: 3b31af3936534a8a96e91cd5f2444602; no voters: 
I20260812 06:18:52.054040 13008 leader_election.cc:290] T 75aa4f4740e04c2982f83579df3c8893 P 3b31af3936534a8a96e91cd5f2444602 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:52.054152 13010 raft_consensus.cc:2804] T 75aa4f4740e04c2982f83579df3c8893 P 3b31af3936534a8a96e91cd5f2444602 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:52.054335 13008 ts_tablet_manager.cc:1434] T 75aa4f4740e04c2982f83579df3c8893 P 3b31af3936534a8a96e91cd5f2444602: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:52.054354 13010 raft_consensus.cc:697] T 75aa4f4740e04c2982f83579df3c8893 P 3b31af3936534a8a96e91cd5f2444602 [term 1 LEADER]: Becoming Leader. State: Replica: 3b31af3936534a8a96e91cd5f2444602, State: Running, Role: LEADER
I20260812 06:18:52.054415 12992 heartbeater.cc:499] Master 127.12.73.126:39469 was elected leader, sending a full tablet report...
I20260812 06:18:52.054483 13010 consensus_queue.cc:237] T 75aa4f4740e04c2982f83579df3c8893 P 3b31af3936534a8a96e91cd5f2444602 [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: "3b31af3936534a8a96e91cd5f2444602" member_type: VOTER last_known_addr { host: "127.12.73.65" port: 42915 } }
I20260812 06:18:52.055816 12840 catalog_manager.cc:5719] T 75aa4f4740e04c2982f83579df3c8893 P 3b31af3936534a8a96e91cd5f2444602 reported cstate change: term changed from 0 to 1, leader changed from <none> to 3b31af3936534a8a96e91cd5f2444602 (127.12.73.65). New cstate: current_term: 1 leader_uuid: "3b31af3936534a8a96e91cd5f2444602" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3b31af3936534a8a96e91cd5f2444602" member_type: VOTER last_known_addr { host: "127.12.73.65" port: 42915 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:52.119216 12581 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.057s	user 0.018s	sys 0.008s
I20260812 06:18:52.271831 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling FlushMRSOp(75aa4f4740e04c2982f83579df3c8893): perf score=19.054940
I20260812 06:18:52.413384 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: FlushMRSOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.141s	user 0.104s	sys 0.036s Metrics: {"bytes_written":12307492,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":61,"dirs.run_cpu_time_us":206,"dirs.run_wall_time_us":831,"drs_written":1,"lbm_read_time_us":42,"lbm_reads_lt_1ms":4,"lbm_write_time_us":34361,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:18:52.414139 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling LogGCOp(75aa4f4740e04c2982f83579df3c8893): free 20743880 bytes of WAL
I20260812 06:18:52.414391 12925 log_reader.cc:385] T 75aa4f4740e04c2982f83579df3c8893: removed 2 log segments from log reader
I20260812 06:18:52.414454 12925 log.cc:1079] T 75aa4f4740e04c2982f83579df3c8893 P 3b31af3936534a8a96e91cd5f2444602: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/75aa4f4740e04c2982f83579df3c8893/wal-000000001 (ops 1-6)
I20260812 06:18:52.414494 12925 log.cc:1079] T 75aa4f4740e04c2982f83579df3c8893 P 3b31af3936534a8a96e91cd5f2444602: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/75aa4f4740e04c2982f83579df3c8893/wal-000000002 (ops 7-11)
I20260812 06:18:52.419376 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: LogGCOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.005s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:18:52.419770 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893): perf score=2.188937
I20260812 06:18:52.437988 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.018s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4894,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:52.438589 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling UndoDeltaBlockGCOp(75aa4f4740e04c2982f83579df3c8893): 16411392 bytes on disk
I20260812 06:18:52.438953 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: UndoDeltaBlockGCOp(75aa4f4740e04c2982f83579df3c8893) 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.439374 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling MajorDeltaCompactionOp(75aa4f4740e04c2982f83579df3c8893): perf score=1.000000
I20260812 06:18:52.570282 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: MajorDeltaCompactionOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.131s	user 0.103s	sys 0.027s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":514,"lbm_read_time_us":10141,"lbm_reads_lt_1ms":460,"lbm_write_time_us":21337,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":329,"threads_started":5,"update_count":2000}
I20260812 06:18:52.570878 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893): perf score=11.118625
I20260812 06:18:52.603279 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.032s	user 0.022s	sys 0.008s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":13535,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:52.603839 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893): perf score=2.188937
I20260812 06:18:52.618403 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.014s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5412,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:52.618839 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling MajorDeltaCompactionOp(75aa4f4740e04c2982f83579df3c8893): perf score=1.000000
I20260812 06:18:52.743053 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: MajorDeltaCompactionOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.124s	user 0.112s	sys 0.012s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":280,"lbm_read_time_us":10098,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21965,"lbm_writes_lt_1ms":443,"mutex_wait_us":73,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:18:52.743593 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893): perf score=10.126437
I20260812 06:18:52.795352 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.052s	user 0.018s	sys 0.027s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16554,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:52.795913 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893): perf score=2.188937
I20260812 06:18:52.806540 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4027,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:52.806991 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling MajorDeltaCompactionOp(75aa4f4740e04c2982f83579df3c8893): perf score=1.000000
I20260812 06:18:52.952674 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: MajorDeltaCompactionOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.146s	user 0.094s	sys 0.052s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":336,"lbm_read_time_us":10388,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21318,"lbm_writes_lt_1ms":443,"mutex_wait_us":56,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11008,"update_count":2000}
I20260812 06:18:52.953343 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893): perf score=10.126437
I20260812 06:18:52.997099 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.044s	user 0.020s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15016,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:52.997619 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893): perf score=2.188937
I20260812 06:18:53.013417 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.016s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5915,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:53.013928 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling MajorDeltaCompactionOp(75aa4f4740e04c2982f83579df3c8893): perf score=1.000000
I20260812 06:18:53.135581 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: MajorDeltaCompactionOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.121s	user 0.105s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":567,"lbm_read_time_us":7970,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22980,"lbm_writes_lt_1ms":443,"mutex_wait_us":39,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":18304,"update_count":2000}
I20260812 06:18:53.136117 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893): perf score=10.126437
I20260812 06:18:53.179177 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.043s	user 0.014s	sys 0.024s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19222,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:18:53.179678 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893): perf score=2.188937
I20260812 06:18:53.189759 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3714,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:53.190388 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling MajorDeltaCompactionOp(75aa4f4740e04c2982f83579df3c8893): perf score=1.000000
I20260812 06:18:53.311568 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: MajorDeltaCompactionOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.121s	user 0.101s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":862,"lbm_read_time_us":8134,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21944,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":2000}
I20260812 06:18:53.312127 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893): perf score=10.126437
I20260812 06:18:53.363198 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.051s	user 0.033s	sys 0.015s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":17869,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:53.363757 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893): perf score=2.188937
I20260812 06:18:53.379462 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.016s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6034,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:53.380062 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling MajorDeltaCompactionOp(75aa4f4740e04c2982f83579df3c8893): perf score=1.000000
I20260812 06:18:53.523583 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: MajorDeltaCompactionOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.143s	user 0.096s	sys 0.047s 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":246,"lbm_read_time_us":11010,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21696,"lbm_writes_lt_1ms":443,"mutex_wait_us":46,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8832,"update_count":2000}
I20260812 06:18:53.524273 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893): perf score=10.126437
I20260812 06:18:53.569411 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.045s	user 0.029s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17455,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:53.569904 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893): perf score=2.188937
I20260812 06:18:53.581416 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.011s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4380,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:53.581959 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling FlushMRSOp(75aa4f4740e04c2982f83579df3c8893): perf score=1.000000
I20260812 06:18:53.610714 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: FlushMRSOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.029s	user 0.027s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":66,"dirs.run_cpu_time_us":253,"dirs.run_wall_time_us":1439,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1261,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:53.611347 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling LogGCOp(75aa4f4740e04c2982f83579df3c8893): free 111786258 bytes of WAL
I20260812 06:18:53.611621 12925 log_reader.cc:385] T 75aa4f4740e04c2982f83579df3c8893: removed 11 log segments from log reader
I20260812 06:18:53.611706 12925 log.cc:1079] T 75aa4f4740e04c2982f83579df3c8893 P 3b31af3936534a8a96e91cd5f2444602: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/75aa4f4740e04c2982f83579df3c8893/wal-000000003 (ops 12-16)
I20260812 06:18:53.611760 12925 log.cc:1079] T 75aa4f4740e04c2982f83579df3c8893 P 3b31af3936534a8a96e91cd5f2444602: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/75aa4f4740e04c2982f83579df3c8893/wal-000000004 (ops 17-20)
I20260812 06:18:53.611807 12925 log.cc:1079] T 75aa4f4740e04c2982f83579df3c8893 P 3b31af3936534a8a96e91cd5f2444602: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/75aa4f4740e04c2982f83579df3c8893/wal-000000005 (ops 21-25)
I20260812 06:18:53.611850 12925 log.cc:1079] T 75aa4f4740e04c2982f83579df3c8893 P 3b31af3936534a8a96e91cd5f2444602: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/75aa4f4740e04c2982f83579df3c8893/wal-000000006 (ops 26-30)
I20260812 06:18:53.611892 12925 log.cc:1079] T 75aa4f4740e04c2982f83579df3c8893 P 3b31af3936534a8a96e91cd5f2444602: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/75aa4f4740e04c2982f83579df3c8893/wal-000000007 (ops 31-35)
I20260812 06:18:53.611924 12925 log.cc:1079] T 75aa4f4740e04c2982f83579df3c8893 P 3b31af3936534a8a96e91cd5f2444602: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/75aa4f4740e04c2982f83579df3c8893/wal-000000008 (ops 36-40)
I20260812 06:18:53.611963 12925 log.cc:1079] T 75aa4f4740e04c2982f83579df3c8893 P 3b31af3936534a8a96e91cd5f2444602: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/75aa4f4740e04c2982f83579df3c8893/wal-000000009 (ops 41-45)
I20260812 06:18:53.611999 12925 log.cc:1079] T 75aa4f4740e04c2982f83579df3c8893 P 3b31af3936534a8a96e91cd5f2444602: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/75aa4f4740e04c2982f83579df3c8893/wal-000000010 (ops 46-50)
I20260812 06:18:53.612035 12925 log.cc:1079] T 75aa4f4740e04c2982f83579df3c8893 P 3b31af3936534a8a96e91cd5f2444602: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/75aa4f4740e04c2982f83579df3c8893/wal-000000011 (ops 51-54)
I20260812 06:18:53.612069 12925 log.cc:1079] T 75aa4f4740e04c2982f83579df3c8893 P 3b31af3936534a8a96e91cd5f2444602: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/75aa4f4740e04c2982f83579df3c8893/wal-000000012 (ops 55-59)
I20260812 06:18:53.612104 12925 log.cc:1079] T 75aa4f4740e04c2982f83579df3c8893 P 3b31af3936534a8a96e91cd5f2444602: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/75aa4f4740e04c2982f83579df3c8893/wal-000000013 (ops 60-64)
I20260812 06:18:53.634774 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: LogGCOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.023s	user 0.002s	sys 0.019s Metrics: {}
I20260812 06:18:53.635392 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling UndoDeltaBlockGCOp(75aa4f4740e04c2982f83579df3c8893): 448 bytes on disk
I20260812 06:18:53.636098 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: UndoDeltaBlockGCOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":72,"lbm_reads_lt_1ms":4}
I20260812 06:18:53.636617 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893): perf score=4.173312
I20260812 06:18:53.660811 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.024s	user 0.006s	sys 0.014s Metrics: {"bytes_written":5456464,"delete_count":0,"lbm_write_time_us":5970,"lbm_writes_lt_1ms":136,"reinsert_count":0,"update_count":665}
I20260812 06:18:53.661433 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893): perf score=1.196750
I20260812 06:18:53.669224 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.008s	user 0.003s	sys 0.005s Metrics: {"bytes_written":2748830,"delete_count":0,"lbm_write_time_us":2745,"lbm_writes_lt_1ms":70,"reinsert_count":0,"update_count":335}
I20260812 06:18:53.669632 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling MajorDeltaCompactionOp(75aa4f4740e04c2982f83579df3c8893): perf score=1.000000
I20260812 06:18:53.859028 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: MajorDeltaCompactionOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.189s	user 0.105s	sys 0.084s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877309,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":611,"lbm_read_time_us":12908,"lbm_reads_lt_1ms":674,"lbm_write_time_us":30974,"lbm_writes_lt_1ms":643,"mutex_wait_us":236,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1280,"thread_start_us":75,"threads_started":1,"update_count":3000}
I20260812 06:18:53.859647 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893): perf score=14.095187
I20260812 06:18:53.910894 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.051s	user 0.030s	sys 0.019s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18352,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:53.911448 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893): perf score=2.188937
I20260812 06:18:53.921970 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4004,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:53.922518 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling MajorDeltaCompactionOp(75aa4f4740e04c2982f83579df3c8893): perf score=1.000000
I20260812 06:18:54.092763 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: MajorDeltaCompactionOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.170s	user 0.113s	sys 0.055s 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":173,"lbm_read_time_us":12354,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25524,"lbm_writes_lt_1ms":543,"mutex_wait_us":2,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2944,"update_count":2500}
I20260812 06:18:54.093436 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893): perf score=11.118625
I20260812 06:18:54.127610 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.034s	user 0.021s	sys 0.010s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":13995,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:54.128119 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893): perf score=2.188937
I20260812 06:18:54.141412 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.013s	user 0.005s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4783,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:54.142024 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling MajorDeltaCompactionOp(75aa4f4740e04c2982f83579df3c8893): perf score=1.000000
I20260812 06:18:54.260215 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: MajorDeltaCompactionOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.118s	user 0.080s	sys 0.035s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":360,"lbm_read_time_us":7063,"lbm_reads_lt_1ms":464,"lbm_write_time_us":19522,"lbm_writes_lt_1ms":443,"mutex_wait_us":2,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:54.261337 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893): perf score=10.126437
I20260812 06:18:54.294425 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.033s	user 0.015s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12188,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:54.294875 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893): perf score=2.188937
I20260812 06:18:54.304821 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3554,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:54.305518 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling MajorDeltaCompactionOp(75aa4f4740e04c2982f83579df3c8893): perf score=1.000000
I20260812 06:18:54.426926 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: MajorDeltaCompactionOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.121s	user 0.088s	sys 0.033s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":685,"lbm_read_time_us":8445,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23567,"lbm_writes_lt_1ms":443,"mutex_wait_us":265,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11008,"update_count":2000}
I20260812 06:18:54.427491 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893): perf score=10.126437
I20260812 06:18:54.465539 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.038s	user 0.025s	sys 0.011s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":16022,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:54.466079 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893): perf score=2.188937
I20260812 06:18:54.477238 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.011s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3572,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:54.477990 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling MajorDeltaCompactionOp(75aa4f4740e04c2982f83579df3c8893): perf score=1.000000
I20260812 06:18:54.593284 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: MajorDeltaCompactionOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.115s	user 0.087s	sys 0.028s 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":362,"lbm_read_time_us":7887,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20728,"lbm_writes_lt_1ms":443,"mutex_wait_us":43,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13312,"update_count":2000}
I20260812 06:18:54.593931 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893): perf score=10.126437
I20260812 06:18:54.643081 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.049s	user 0.016s	sys 0.031s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16266,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:54.644163 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893): perf score=2.188937
I20260812 06:18:54.661688 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.017s	user 0.009s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6520,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:54.662273 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling MajorDeltaCompactionOp(75aa4f4740e04c2982f83579df3c8893): perf score=1.000000
I20260812 06:18:54.814182 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: MajorDeltaCompactionOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.152s	user 0.099s	sys 0.052s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":993,"lbm_read_time_us":10722,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23722,"lbm_writes_lt_1ms":443,"mutex_wait_us":29,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:18:54.814842 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893): perf score=10.126437
I20260812 06:18:54.851435 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.036s	user 0.013s	sys 0.022s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13573,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:54.852010 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893): perf score=2.188937
I20260812 06:18:54.867705 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.016s	user 0.006s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5829,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:54.868299 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling MajorDeltaCompactionOp(75aa4f4740e04c2982f83579df3c8893): perf score=1.000000
I20260812 06:18:54.987228 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: MajorDeltaCompactionOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.119s	user 0.094s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":636,"lbm_read_time_us":7587,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23410,"lbm_writes_lt_1ms":443,"mutex_wait_us":275,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:54.987833 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893): perf score=10.126437
I20260812 06:18:55.025455 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.037s	user 0.022s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17365,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:18:55.025996 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893): perf score=2.188937
I20260812 06:18:55.036329 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3865,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:55.037005 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling FlushMRSOp(75aa4f4740e04c2982f83579df3c8893): perf score=1.000000
I20260812 06:18:55.067116 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: FlushMRSOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.029s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":103,"dirs.run_cpu_time_us":184,"dirs.run_wall_time_us":1369,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1540,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:55.067862 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling LogGCOp(75aa4f4740e04c2982f83579df3c8893): free 133477427 bytes of WAL
I20260812 06:18:55.068113 12925 log_reader.cc:385] T 75aa4f4740e04c2982f83579df3c8893: removed 13 log segments from log reader
I20260812 06:18:55.068164 12925 log.cc:1079] T 75aa4f4740e04c2982f83579df3c8893 P 3b31af3936534a8a96e91cd5f2444602: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/75aa4f4740e04c2982f83579df3c8893/wal-000000014 (ops 65-69)
I20260812 06:18:55.068202 12925 log.cc:1079] T 75aa4f4740e04c2982f83579df3c8893 P 3b31af3936534a8a96e91cd5f2444602: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/75aa4f4740e04c2982f83579df3c8893/wal-000000015 (ops 70-74)
I20260812 06:18:55.068234 12925 log.cc:1079] T 75aa4f4740e04c2982f83579df3c8893 P 3b31af3936534a8a96e91cd5f2444602: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/75aa4f4740e04c2982f83579df3c8893/wal-000000016 (ops 75-79)
I20260812 06:18:55.068259 12925 log.cc:1079] T 75aa4f4740e04c2982f83579df3c8893 P 3b31af3936534a8a96e91cd5f2444602: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/75aa4f4740e04c2982f83579df3c8893/wal-000000017 (ops 80-84)
I20260812 06:18:55.068290 12925 log.cc:1079] T 75aa4f4740e04c2982f83579df3c8893 P 3b31af3936534a8a96e91cd5f2444602: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/75aa4f4740e04c2982f83579df3c8893/wal-000000018 (ops 85-89)
I20260812 06:18:55.068321 12925 log.cc:1079] T 75aa4f4740e04c2982f83579df3c8893 P 3b31af3936534a8a96e91cd5f2444602: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/75aa4f4740e04c2982f83579df3c8893/wal-000000019 (ops 90-94)
I20260812 06:18:55.068351 12925 log.cc:1079] T 75aa4f4740e04c2982f83579df3c8893 P 3b31af3936534a8a96e91cd5f2444602: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/75aa4f4740e04c2982f83579df3c8893/wal-000000020 (ops 95-99)
I20260812 06:18:55.068379 12925 log.cc:1079] T 75aa4f4740e04c2982f83579df3c8893 P 3b31af3936534a8a96e91cd5f2444602: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/75aa4f4740e04c2982f83579df3c8893/wal-000000021 (ops 100-104)
I20260812 06:18:55.068408 12925 log.cc:1079] T 75aa4f4740e04c2982f83579df3c8893 P 3b31af3936534a8a96e91cd5f2444602: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/75aa4f4740e04c2982f83579df3c8893/wal-000000022 (ops 105-109)
I20260812 06:18:55.068439 12925 log.cc:1079] T 75aa4f4740e04c2982f83579df3c8893 P 3b31af3936534a8a96e91cd5f2444602: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/75aa4f4740e04c2982f83579df3c8893/wal-000000023 (ops 110-114)
I20260812 06:18:55.068467 12925 log.cc:1079] T 75aa4f4740e04c2982f83579df3c8893 P 3b31af3936534a8a96e91cd5f2444602: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/75aa4f4740e04c2982f83579df3c8893/wal-000000024 (ops 115-119)
I20260812 06:18:55.068496 12925 log.cc:1079] T 75aa4f4740e04c2982f83579df3c8893 P 3b31af3936534a8a96e91cd5f2444602: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/75aa4f4740e04c2982f83579df3c8893/wal-000000025 (ops 120-124)
I20260812 06:18:55.068526 12925 log.cc:1079] T 75aa4f4740e04c2982f83579df3c8893 P 3b31af3936534a8a96e91cd5f2444602: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/75aa4f4740e04c2982f83579df3c8893/wal-000000026 (ops 125-129)
I20260812 06:18:55.092718 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: LogGCOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.025s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:18:55.093196 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893): perf score=3.181125
I20260812 06:18:55.104753 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":4475,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:55.105248 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling UndoDeltaBlockGCOp(75aa4f4740e04c2982f83579df3c8893): 482 bytes on disk
I20260812 06:18:55.105693 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: UndoDeltaBlockGCOp(75aa4f4740e04c2982f83579df3c8893) 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:55.106281 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893): perf score=2.188937
I20260812 06:18:55.115448 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.009s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3354,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:55.115846 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling MajorDeltaCompactionOp(75aa4f4740e04c2982f83579df3c8893): perf score=1.000000
I20260812 06:18:55.280404 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: MajorDeltaCompactionOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.164s	user 0.114s	sys 0.045s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877328,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":631,"lbm_read_time_us":11492,"lbm_reads_lt_1ms":674,"lbm_write_time_us":29303,"lbm_writes_lt_1ms":643,"mutex_wait_us":50,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":49792,"thread_start_us":109,"threads_started":1,"update_count":3000}
I20260812 06:18:55.280967 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893): perf score=14.095187
I20260812 06:18:55.326865 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.046s	user 0.026s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18415,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:55.327471 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893): perf score=2.188937
I20260812 06:18:55.343526 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.016s	user 0.002s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6230,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:55.344199 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling MajorDeltaCompactionOp(75aa4f4740e04c2982f83579df3c8893): perf score=1.000000
I20260812 06:18:55.490751 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: MajorDeltaCompactionOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.146s	user 0.110s	sys 0.035s 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":969,"lbm_read_time_us":8909,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27373,"lbm_writes_lt_1ms":543,"mutex_wait_us":308,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:55.491392 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893): perf score=12.110812
I20260812 06:18:55.527570 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.036s	user 0.030s	sys 0.004s Metrics: {"bytes_written":13907427,"delete_count":0,"lbm_write_time_us":15040,"lbm_writes_lt_1ms":342,"reinsert_count":0,"update_count":1695}
I20260812 06:18:55.528918 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893): perf score=1.196750
I20260812 06:18:55.543016 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.013s	user 0.005s	sys 0.004s Metrics: {"bytes_written":2912934,"delete_count":0,"lbm_write_time_us":4041,"lbm_writes_lt_1ms":74,"reinsert_count":0,"update_count":355}
I20260812 06:18:55.543660 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling MajorDeltaCompactionOp(75aa4f4740e04c2982f83579df3c8893): perf score=1.000000
I20260812 06:18:55.689934 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: MajorDeltaCompactionOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.146s	user 0.103s	sys 0.032s Metrics: {"cfile_cache_miss":442,"cfile_cache_miss_bytes":21082489,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":779,"lbm_read_time_us":9658,"lbm_reads_lt_1ms":474,"lbm_write_time_us":22797,"lbm_writes_lt_1ms":453,"mutex_wait_us":207,"peak_mem_usage":51099678,"reinsert_count":0,"spinlock_wait_cycles":8064,"update_count":2050}
I20260812 06:18:55.690529 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893): perf score=14.095187
I20260812 06:18:55.734315 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.044s	user 0.035s	sys 0.007s Metrics: {"bytes_written":15999660,"delete_count":0,"lbm_write_time_us":18554,"lbm_writes_lt_1ms":393,"reinsert_count":0,"update_count":1950}
I20260812 06:18:55.734869 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893): perf score=2.188937
I20260812 06:18:55.758512 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.023s	user 0.007s	sys 0.015s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6197,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:55.759238 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling MajorDeltaCompactionOp(75aa4f4740e04c2982f83579df3c8893): perf score=1.000000
I20260812 06:18:55.942589 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: MajorDeltaCompactionOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.183s	user 0.134s	sys 0.036s Metrics: {"cfile_cache_miss":522,"cfile_cache_miss_bytes":24364447,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":590,"lbm_read_time_us":13310,"lbm_reads_lt_1ms":562,"lbm_write_time_us":26565,"lbm_writes_lt_1ms":533,"mutex_wait_us":276,"peak_mem_usage":61665166,"reinsert_count":0,"spinlock_wait_cycles":12672,"update_count":2450}
I20260812 06:18:55.943097 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893): perf score=14.095187
I20260812 06:18:55.994745 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.051s	user 0.022s	sys 0.028s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22413,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:55.995327 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893): perf score=2.188937
I20260812 06:18:56.007824 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4683,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:56.008569 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling MajorDeltaCompactionOp(75aa4f4740e04c2982f83579df3c8893): perf score=1.000000
I20260812 06:18:56.163619 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: MajorDeltaCompactionOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.155s	user 0.112s	sys 0.032s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":209,"lbm_read_time_us":11493,"lbm_reads_lt_1ms":564,"lbm_write_time_us":25331,"lbm_writes_lt_1ms":543,"mutex_wait_us":25,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":71552,"update_count":2500}
I20260812 06:18:56.164157 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893): perf score=14.095187
I20260812 06:18:56.216218 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.052s	user 0.026s	sys 0.012s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":17586,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:56.216810 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893): perf score=2.188937
I20260812 06:18:56.232621 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.016s	user 0.006s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6114,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:56.233259 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling MajorDeltaCompactionOp(75aa4f4740e04c2982f83579df3c8893): perf score=1.000000
I20260812 06:18:56.371258 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: MajorDeltaCompactionOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.138s	user 0.120s	sys 0.016s 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":516,"lbm_read_time_us":8873,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26430,"lbm_writes_lt_1ms":543,"mutex_wait_us":243,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":15872,"update_count":2500}
I20260812 06:18:56.371807 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893): perf score=11.118625
I20260812 06:18:56.407564 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.036s	user 0.025s	sys 0.008s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":14736,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:56.408771 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893): perf score=2.188937
I20260812 06:18:56.432807 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.024s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5015,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:56.433442 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893): perf score=2.188937
I20260812 06:18:56.443658 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3546,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:56.444278 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling FlushMRSOp(75aa4f4740e04c2982f83579df3c8893): perf score=1.000000
I20260812 06:18:56.473966 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: FlushMRSOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.029s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":381,"dirs.run_cpu_time_us":163,"dirs.run_wall_time_us":1379,"drs_written":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1568,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:56.474663 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling LogGCOp(75aa4f4740e04c2982f83579df3c8893): free 124710517 bytes of WAL
I20260812 06:18:56.474898 12925 log_reader.cc:385] T 75aa4f4740e04c2982f83579df3c8893: removed 12 log segments from log reader
I20260812 06:18:56.474960 12925 log.cc:1079] T 75aa4f4740e04c2982f83579df3c8893 P 3b31af3936534a8a96e91cd5f2444602: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/75aa4f4740e04c2982f83579df3c8893/wal-000000027 (ops 130-134)
I20260812 06:18:56.475003 12925 log.cc:1079] T 75aa4f4740e04c2982f83579df3c8893 P 3b31af3936534a8a96e91cd5f2444602: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/75aa4f4740e04c2982f83579df3c8893/wal-000000028 (ops 135-139)
I20260812 06:18:56.475034 12925 log.cc:1079] T 75aa4f4740e04c2982f83579df3c8893 P 3b31af3936534a8a96e91cd5f2444602: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/75aa4f4740e04c2982f83579df3c8893/wal-000000029 (ops 140-144)
I20260812 06:18:56.475059 12925 log.cc:1079] T 75aa4f4740e04c2982f83579df3c8893 P 3b31af3936534a8a96e91cd5f2444602: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/75aa4f4740e04c2982f83579df3c8893/wal-000000030 (ops 145-149)
I20260812 06:18:56.475090 12925 log.cc:1079] T 75aa4f4740e04c2982f83579df3c8893 P 3b31af3936534a8a96e91cd5f2444602: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/75aa4f4740e04c2982f83579df3c8893/wal-000000031 (ops 150-154)
I20260812 06:18:56.475119 12925 log.cc:1079] T 75aa4f4740e04c2982f83579df3c8893 P 3b31af3936534a8a96e91cd5f2444602: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/75aa4f4740e04c2982f83579df3c8893/wal-000000032 (ops 155-159)
I20260812 06:18:56.475147 12925 log.cc:1079] T 75aa4f4740e04c2982f83579df3c8893 P 3b31af3936534a8a96e91cd5f2444602: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/75aa4f4740e04c2982f83579df3c8893/wal-000000033 (ops 160-164)
I20260812 06:18:56.475170 12925 log.cc:1079] T 75aa4f4740e04c2982f83579df3c8893 P 3b31af3936534a8a96e91cd5f2444602: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/75aa4f4740e04c2982f83579df3c8893/wal-000000034 (ops 165-169)
I20260812 06:18:56.475199 12925 log.cc:1079] T 75aa4f4740e04c2982f83579df3c8893 P 3b31af3936534a8a96e91cd5f2444602: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/75aa4f4740e04c2982f83579df3c8893/wal-000000035 (ops 170-174)
I20260812 06:18:56.475231 12925 log.cc:1079] T 75aa4f4740e04c2982f83579df3c8893 P 3b31af3936534a8a96e91cd5f2444602: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/75aa4f4740e04c2982f83579df3c8893/wal-000000036 (ops 175-179)
I20260812 06:18:56.475260 12925 log.cc:1079] T 75aa4f4740e04c2982f83579df3c8893 P 3b31af3936534a8a96e91cd5f2444602: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/75aa4f4740e04c2982f83579df3c8893/wal-000000037 (ops 180-184)
I20260812 06:18:56.475288 12925 log.cc:1079] T 75aa4f4740e04c2982f83579df3c8893 P 3b31af3936534a8a96e91cd5f2444602: Deleting log segment in path: /tmp/dist-test-taskNOLik3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515526611737-12581-0/minicluster-data/ts-0-root/wals/75aa4f4740e04c2982f83579df3c8893/wal-000000038 (ops 185-189)
I20260812 06:18:56.500519 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: LogGCOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.026s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:18:56.501093 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893): perf score=3.181125
I20260812 06:18:56.515313 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.014s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4512904,"delete_count":0,"lbm_write_time_us":4239,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:56.515811 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling UndoDeltaBlockGCOp(75aa4f4740e04c2982f83579df3c8893): 482 bytes on disk
I20260812 06:18:56.516258 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: UndoDeltaBlockGCOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":69,"lbm_reads_lt_1ms":4}
I20260812 06:18:56.516804 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893): perf score=2.188937
I20260812 06:18:56.540105 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.023s	user 0.013s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4966,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:56.540882 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling MajorDeltaCompactionOp(75aa4f4740e04c2982f83579df3c8893): perf score=1.000000
I20260812 06:18:56.735205 12581 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.616s	user 1.760s	sys 0.126s
I20260812 06:18:56.753118 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: MajorDeltaCompactionOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.212s	user 0.135s	sys 0.075s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979851,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"lbm_read_time_us":14726,"lbm_reads_lt_1ms":771,"lbm_write_time_us":34853,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":4480,"update_count":3500}
I20260812 06:18:56.753729 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893): perf score=14.095187
I20260812 06:18:56.785094 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: FlushDeltaMemStoresOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.031s	user 0.022s	sys 0.008s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":14492,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:18:56.785590 12994 maintenance_manager.cc:419] P 3b31af3936534a8a96e91cd5f2444602: Scheduling MajorDeltaCompactionOp(75aa4f4740e04c2982f83579df3c8893): perf score=1.000000
I20260812 06:18:56.827064 12581 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.092s	user 0.001s	sys 0.000s
I20260812 06:18:56.827553 12581 tablet_server.cc:179] TabletServer@127.12.73.65:0 shutting down...
I20260812 06:18:56.929852 12925 maintenance_manager.cc:643] P 3b31af3936534a8a96e91cd5f2444602: MajorDeltaCompactionOp(75aa4f4740e04c2982f83579df3c8893) complete. Timing: real 0.144s	user 0.089s	sys 0.049s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672158,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":279,"lbm_read_time_us":9751,"lbm_reads_lt_1ms":467,"lbm_write_time_us":21080,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":18304,"update_count":2000}
I20260812 06:18:56.930527 12581 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:56.930836 12581 tablet_replica.cc:333] T 75aa4f4740e04c2982f83579df3c8893 P 3b31af3936534a8a96e91cd5f2444602: stopping tablet replica
I20260812 06:18:56.930990 12581 raft_consensus.cc:2243] T 75aa4f4740e04c2982f83579df3c8893 P 3b31af3936534a8a96e91cd5f2444602 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:56.931150 12581 raft_consensus.cc:2272] T 75aa4f4740e04c2982f83579df3c8893 P 3b31af3936534a8a96e91cd5f2444602 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:56.936159 12581 tablet_server.cc:196] TabletServer@127.12.73.65:0 shutdown complete.
I20260812 06:18:56.968642 12581 master.cc:562] Master@127.12.73.126:39469 shutting down...
I20260812 06:18:56.972167 12581 raft_consensus.cc:2243] T 00000000000000000000000000000000 P ac18bf16aef541879912ce9ab382e2e5 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:56.972373 12581 raft_consensus.cc:2272] T 00000000000000000000000000000000 P ac18bf16aef541879912ce9ab382e2e5 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:56.972429 12581 tablet_replica.cc:333] T 00000000000000000000000000000000 P ac18bf16aef541879912ce9ab382e2e5: stopping tablet replica
I20260812 06:18:56.985524 12581 master.cc:584] Master@127.12.73.126:39469 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5176 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10435 ms total)

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