[==========] 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:57.873936 10991 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.10.187.254:38721
I20260812 06:18:57.874914 10991 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:57.875506 10991 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:57.881613 10999 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:57.881608 10996 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:57.881891 10991 server_base.cc:1061] running on GCE node
W20260812 06:18:57.881937 10997 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:57.882464 10991 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:57.882550 10991 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:57.882578 10991 hybrid_clock.cc:648] HybridClock initialized: now 1786515537882577 us; error 0 us; skew 500 ppm
I20260812 06:18:57.884254 10991 webserver.cc:533] Webserver started at http://127.10.187.254:37901/ using document root <none> and password file <none>
I20260812 06:18:57.884720 10991 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:57.884774 10991 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:57.884951 10991 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:57.886526 10991 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537863371-10991-0/minicluster-data/master-0-root/instance:
uuid: "5641d653355447018cb617a8de8c6b9b"
format_stamp: "Formatted at 2026-08-12 06:18:57 on dist-test-slave-bxbt"
I20260812 06:18:57.889840 10991 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.005s	sys 0.000s
I20260812 06:18:57.891731 11004 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:57.892724 10991 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:57.892817 10991 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537863371-10991-0/minicluster-data/master-0-root
uuid: "5641d653355447018cb617a8de8c6b9b"
format_stamp: "Formatted at 2026-08-12 06:18:57 on dist-test-slave-bxbt"
I20260812 06:18:57.892902 10991 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537863371-10991-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537863371-10991-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537863371-10991-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:57.906723 10991 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:57.907204 10991 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:57.907334 10991 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:57.914597 10991 rpc_server.cc:307] RPC server started. Bound to: 127.10.187.254:38721
I20260812 06:18:57.914608 11056 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.10.187.254:38721 every 8 connection(s)
I20260812 06:18:57.916685 11057 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:57.921716 11057 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 5641d653355447018cb617a8de8c6b9b: Bootstrap starting.
I20260812 06:18:57.923913 11057 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 5641d653355447018cb617a8de8c6b9b: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:57.924762 11057 log.cc:826] T 00000000000000000000000000000000 P 5641d653355447018cb617a8de8c6b9b: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:57.926283 11057 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 5641d653355447018cb617a8de8c6b9b: No bootstrap required, opened a new log
I20260812 06:18:57.928884 11057 raft_consensus.cc:359] T 00000000000000000000000000000000 P 5641d653355447018cb617a8de8c6b9b [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5641d653355447018cb617a8de8c6b9b" member_type: VOTER }
I20260812 06:18:57.929028 11057 raft_consensus.cc:385] T 00000000000000000000000000000000 P 5641d653355447018cb617a8de8c6b9b [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:57.929133 11057 raft_consensus.cc:740] T 00000000000000000000000000000000 P 5641d653355447018cb617a8de8c6b9b [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 5641d653355447018cb617a8de8c6b9b, State: Initialized, Role: FOLLOWER
I20260812 06:18:57.929702 11057 consensus_queue.cc:260] T 00000000000000000000000000000000 P 5641d653355447018cb617a8de8c6b9b [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: "5641d653355447018cb617a8de8c6b9b" member_type: VOTER }
I20260812 06:18:57.929867 11057 raft_consensus.cc:399] T 00000000000000000000000000000000 P 5641d653355447018cb617a8de8c6b9b [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:57.929940 11057 raft_consensus.cc:493] T 00000000000000000000000000000000 P 5641d653355447018cb617a8de8c6b9b [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:57.930104 11057 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 5641d653355447018cb617a8de8c6b9b [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:57.930837 11057 raft_consensus.cc:515] T 00000000000000000000000000000000 P 5641d653355447018cb617a8de8c6b9b [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5641d653355447018cb617a8de8c6b9b" member_type: VOTER }
I20260812 06:18:57.931246 11057 leader_election.cc:304] T 00000000000000000000000000000000 P 5641d653355447018cb617a8de8c6b9b [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: 5641d653355447018cb617a8de8c6b9b; no voters: 
I20260812 06:18:57.931543 11057 leader_election.cc:290] T 00000000000000000000000000000000 P 5641d653355447018cb617a8de8c6b9b [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:57.931675 11060 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 5641d653355447018cb617a8de8c6b9b [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:57.931991 11060 raft_consensus.cc:697] T 00000000000000000000000000000000 P 5641d653355447018cb617a8de8c6b9b [term 1 LEADER]: Becoming Leader. State: Replica: 5641d653355447018cb617a8de8c6b9b, State: Running, Role: LEADER
I20260812 06:18:57.932400 11060 consensus_queue.cc:237] T 00000000000000000000000000000000 P 5641d653355447018cb617a8de8c6b9b [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: "5641d653355447018cb617a8de8c6b9b" member_type: VOTER }
I20260812 06:18:57.932492 11057 sys_catalog.cc:565] T 00000000000000000000000000000000 P 5641d653355447018cb617a8de8c6b9b [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:57.934219 11062 sys_catalog.cc:455] T 00000000000000000000000000000000 P 5641d653355447018cb617a8de8c6b9b [sys.catalog]: SysCatalogTable state changed. Reason: New leader 5641d653355447018cb617a8de8c6b9b. Latest consensus state: current_term: 1 leader_uuid: "5641d653355447018cb617a8de8c6b9b" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5641d653355447018cb617a8de8c6b9b" member_type: VOTER } }
I20260812 06:18:57.934293 11061 sys_catalog.cc:455] T 00000000000000000000000000000000 P 5641d653355447018cb617a8de8c6b9b [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "5641d653355447018cb617a8de8c6b9b" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5641d653355447018cb617a8de8c6b9b" member_type: VOTER } }
I20260812 06:18:57.934352 11062 sys_catalog.cc:458] T 00000000000000000000000000000000 P 5641d653355447018cb617a8de8c6b9b [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:57.934386 11061 sys_catalog.cc:458] T 00000000000000000000000000000000 P 5641d653355447018cb617a8de8c6b9b [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:57.934764 11072 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:57.935032 10991 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:57.936949 11072 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:57.941423 11072 catalog_manager.cc:1383] Generated new cluster ID: d14b4f47b2e54f748da7a8952df0abbd
I20260812 06:18:57.941488 11072 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:57.966311 11072 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:57.967506 11072 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:57.984076 11072 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 5641d653355447018cb617a8de8c6b9b: Generated new TSK 0
I20260812 06:18:57.984772 11072 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:58.000168 10991 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:58.003161 11080 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:58.003295 11082 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:58.003413 10991 server_base.cc:1061] running on GCE node
W20260812 06:18:58.003546 11079 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:58.003813 10991 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:58.003861 10991 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:58.003877 10991 hybrid_clock.cc:648] HybridClock initialized: now 1786515538003877 us; error 0 us; skew 500 ppm
I20260812 06:18:58.004801 10991 webserver.cc:533] Webserver started at http://127.10.187.193:34649/ using document root <none> and password file <none>
I20260812 06:18:58.005007 10991 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:58.005059 10991 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:58.005162 10991 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:58.005592 10991 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537863371-10991-0/minicluster-data/ts-0-root/instance:
uuid: "0219890e41ee4068925481d81e10ff00"
format_stamp: "Formatted at 2026-08-12 06:18:58 on dist-test-slave-bxbt"
I20260812 06:18:58.007117 10991 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.001s
I20260812 06:18:58.008250 11087 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:58.008500 10991 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.000s
I20260812 06:18:58.008581 10991 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537863371-10991-0/minicluster-data/ts-0-root
uuid: "0219890e41ee4068925481d81e10ff00"
format_stamp: "Formatted at 2026-08-12 06:18:58 on dist-test-slave-bxbt"
I20260812 06:18:58.008756 10991 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537863371-10991-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537863371-10991-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537863371-10991-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:58.020830 10991 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:58.021255 10991 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:58.021749 10991 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:58.022603 10991 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:58.022655 10991 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:58.022720 10991 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:58.022761 10991 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:58.029743 10991 rpc_server.cc:307] RPC server started. Bound to: 127.10.187.193:33879
I20260812 06:18:58.029776 11150 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.10.187.193:33879 every 8 connection(s)
I20260812 06:18:58.044514 11151 heartbeater.cc:344] Connected to a master server at 127.10.187.254:38721
I20260812 06:18:58.044770 11151 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:58.045230 11151 heartbeater.cc:507] Master 127.10.187.254:38721 requested a full tablet report, sending...
I20260812 06:18:58.046566 11021 ts_manager.cc:194] Registered new tserver with Master: 0219890e41ee4068925481d81e10ff00 (127.10.187.193:33879)
I20260812 06:18:58.047013 10991 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.016630241s
I20260812 06:18:58.047802 11021 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:50352
I20260812 06:18:58.056191 11021 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:50354:
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:58.070539 11115 tablet_service.cc:1511] Processing CreateTablet for tablet 33781891b3e04535829fb030f881db47 (DEFAULT_TABLE table=heavy-update-compaction-test [id=97e490ba45da423c9cc0a3a1b5838b9b]), partition=
I20260812 06:18:58.071005 11115 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 33781891b3e04535829fb030f881db47. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:58.073330 11163 tablet_bootstrap.cc:492] T 33781891b3e04535829fb030f881db47 P 0219890e41ee4068925481d81e10ff00: Bootstrap starting.
I20260812 06:18:58.074515 11163 tablet_bootstrap.cc:654] T 33781891b3e04535829fb030f881db47 P 0219890e41ee4068925481d81e10ff00: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:58.075644 11163 tablet_bootstrap.cc:492] T 33781891b3e04535829fb030f881db47 P 0219890e41ee4068925481d81e10ff00: No bootstrap required, opened a new log
I20260812 06:18:58.075801 11163 ts_tablet_manager.cc:1403] T 33781891b3e04535829fb030f881db47 P 0219890e41ee4068925481d81e10ff00: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:18:58.076222 11163 raft_consensus.cc:359] T 33781891b3e04535829fb030f881db47 P 0219890e41ee4068925481d81e10ff00 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0219890e41ee4068925481d81e10ff00" member_type: VOTER last_known_addr { host: "127.10.187.193" port: 33879 } }
I20260812 06:18:58.076357 11163 raft_consensus.cc:385] T 33781891b3e04535829fb030f881db47 P 0219890e41ee4068925481d81e10ff00 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:58.076409 11163 raft_consensus.cc:740] T 33781891b3e04535829fb030f881db47 P 0219890e41ee4068925481d81e10ff00 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 0219890e41ee4068925481d81e10ff00, State: Initialized, Role: FOLLOWER
I20260812 06:18:58.076560 11163 consensus_queue.cc:260] T 33781891b3e04535829fb030f881db47 P 0219890e41ee4068925481d81e10ff00 [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: "0219890e41ee4068925481d81e10ff00" member_type: VOTER last_known_addr { host: "127.10.187.193" port: 33879 } }
I20260812 06:18:58.076691 11163 raft_consensus.cc:399] T 33781891b3e04535829fb030f881db47 P 0219890e41ee4068925481d81e10ff00 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:58.076743 11163 raft_consensus.cc:493] T 33781891b3e04535829fb030f881db47 P 0219890e41ee4068925481d81e10ff00 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:58.076800 11163 raft_consensus.cc:3060] T 33781891b3e04535829fb030f881db47 P 0219890e41ee4068925481d81e10ff00 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:58.078145 11163 raft_consensus.cc:515] T 33781891b3e04535829fb030f881db47 P 0219890e41ee4068925481d81e10ff00 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0219890e41ee4068925481d81e10ff00" member_type: VOTER last_known_addr { host: "127.10.187.193" port: 33879 } }
I20260812 06:18:58.078315 11163 leader_election.cc:304] T 33781891b3e04535829fb030f881db47 P 0219890e41ee4068925481d81e10ff00 [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: 0219890e41ee4068925481d81e10ff00; no voters: 
I20260812 06:18:58.078567 11163 leader_election.cc:290] T 33781891b3e04535829fb030f881db47 P 0219890e41ee4068925481d81e10ff00 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:58.078668 11165 raft_consensus.cc:2804] T 33781891b3e04535829fb030f881db47 P 0219890e41ee4068925481d81e10ff00 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:58.078857 11165 raft_consensus.cc:697] T 33781891b3e04535829fb030f881db47 P 0219890e41ee4068925481d81e10ff00 [term 1 LEADER]: Becoming Leader. State: Replica: 0219890e41ee4068925481d81e10ff00, State: Running, Role: LEADER
I20260812 06:18:58.078958 11163 ts_tablet_manager.cc:1434] T 33781891b3e04535829fb030f881db47 P 0219890e41ee4068925481d81e10ff00: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:58.079032 11165 consensus_queue.cc:237] T 33781891b3e04535829fb030f881db47 P 0219890e41ee4068925481d81e10ff00 [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: "0219890e41ee4068925481d81e10ff00" member_type: VOTER last_known_addr { host: "127.10.187.193" port: 33879 } }
I20260812 06:18:58.079392 11151 heartbeater.cc:499] Master 127.10.187.254:38721 was elected leader, sending a full tablet report...
I20260812 06:18:58.082113 11021 catalog_manager.cc:5719] T 33781891b3e04535829fb030f881db47 P 0219890e41ee4068925481d81e10ff00 reported cstate change: term changed from 0 to 1, leader changed from <none> to 0219890e41ee4068925481d81e10ff00 (127.10.187.193). New cstate: current_term: 1 leader_uuid: "0219890e41ee4068925481d81e10ff00" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0219890e41ee4068925481d81e10ff00" member_type: VOTER last_known_addr { host: "127.10.187.193" port: 33879 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:58.145619 10991 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.055s	user 0.018s	sys 0.008s
I20260812 06:18:58.280826 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling FlushMRSOp(33781891b3e04535829fb030f881db47): perf score=19.054940
I20260812 06:18:58.461381 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: FlushMRSOp(33781891b3e04535829fb030f881db47) complete. Timing: real 0.180s	user 0.145s	sys 0.032s Metrics: {"bytes_written":14112552,"cfile_init":1,"compiler_manager_pool.queue_time_us":211,"delete_count":0,"dirs.queue_time_us":69,"dirs.run_cpu_time_us":267,"dirs.run_wall_time_us":838,"drs_written":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4,"lbm_write_time_us":44097,"lbm_writes_lt_1ms":801,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":116608,"thread_start_us":140,"threads_started":1,"update_count":1720}
I20260812 06:18:58.462426 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling LogGCOp(33781891b3e04535829fb030f881db47): free 20743880 bytes of WAL
I20260812 06:18:58.462730 11092 log_reader.cc:385] T 33781891b3e04535829fb030f881db47: removed 2 log segments from log reader
I20260812 06:18:58.462812 11092 log.cc:1079] T 33781891b3e04535829fb030f881db47 P 0219890e41ee4068925481d81e10ff00: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/33781891b3e04535829fb030f881db47/wal-000000001 (ops 1-6)
I20260812 06:18:58.462883 11092 log.cc:1079] T 33781891b3e04535829fb030f881db47 P 0219890e41ee4068925481d81e10ff00: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/33781891b3e04535829fb030f881db47/wal-000000002 (ops 7-11)
I20260812 06:18:58.466774 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: LogGCOp(33781891b3e04535829fb030f881db47) complete. Timing: real 0.004s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:18:58.467100 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47): perf score=1.196750
I20260812 06:18:58.490653 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47) complete. Timing: real 0.023s	user 0.006s	sys 0.005s Metrics: {"bytes_written":2707809,"delete_count":0,"lbm_write_time_us":2494,"lbm_writes_lt_1ms":69,"reinsert_count":0,"update_count":330}
I20260812 06:18:58.491166 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47): perf score=2.188937
I20260812 06:18:58.500875 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3548,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:58.501313 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling MajorDeltaCompactionOp(33781891b3e04535829fb030f881db47): perf score=1.000000
I20260812 06:18:58.673815 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: MajorDeltaCompactionOp(33781891b3e04535829fb030f881db47) complete. Timing: real 0.172s	user 0.127s	sys 0.045s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774766,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":450,"lbm_read_time_us":11649,"lbm_reads_lt_1ms":573,"lbm_write_time_us":27257,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":235,"threads_started":5,"update_count":2500}
I20260812 06:18:58.674351 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling UndoDeltaBlockGCOp(33781891b3e04535829fb030f881db47): 16411398 bytes on disk
I20260812 06:18:58.675323 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: UndoDeltaBlockGCOp(33781891b3e04535829fb030f881db47) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":71,"lbm_reads_lt_1ms":4}
I20260812 06:18:58.675804 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47): perf score=10.126437
I20260812 06:18:58.722860 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47) complete. Timing: real 0.047s	user 0.013s	sys 0.020s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":15852,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:58.723416 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47): perf score=2.188937
I20260812 06:18:58.733526 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3851,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:58.734067 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling MajorDeltaCompactionOp(33781891b3e04535829fb030f881db47): perf score=1.000000
I20260812 06:18:58.861403 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: MajorDeltaCompactionOp(33781891b3e04535829fb030f881db47) complete. Timing: real 0.127s	user 0.102s	sys 0.023s 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":185,"lbm_read_time_us":9008,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24168,"lbm_writes_lt_1ms":443,"mutex_wait_us":39,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9344,"update_count":2000}
I20260812 06:18:58.862018 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47): perf score=10.126437
I20260812 06:18:58.907205 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47) complete. Timing: real 0.045s	user 0.019s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14236,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:58.907626 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47): perf score=2.188937
I20260812 06:18:58.918360 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4094,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:58.919109 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling MajorDeltaCompactionOp(33781891b3e04535829fb030f881db47): perf score=1.000000
I20260812 06:18:59.033035 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: MajorDeltaCompactionOp(33781891b3e04535829fb030f881db47) complete. Timing: real 0.114s	user 0.097s	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":1450,"lbm_read_time_us":8402,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21053,"lbm_writes_lt_1ms":443,"mutex_wait_us":292,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10496,"update_count":2000}
I20260812 06:18:59.033644 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47): perf score=10.126437
I20260812 06:18:59.069656 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47) complete. Timing: real 0.036s	user 0.018s	sys 0.016s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15460,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":1500}
I20260812 06:18:59.070196 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47): perf score=2.188937
I20260812 06:18:59.084326 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47) complete. Timing: real 0.014s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5572,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:59.084864 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling MajorDeltaCompactionOp(33781891b3e04535829fb030f881db47): perf score=1.000000
I20260812 06:18:59.208629 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: MajorDeltaCompactionOp(33781891b3e04535829fb030f881db47) complete. Timing: real 0.124s	user 0.103s	sys 0.020s 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":494,"lbm_read_time_us":8471,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23946,"lbm_writes_lt_1ms":443,"mutex_wait_us":38,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:59.209177 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47): perf score=10.126437
I20260812 06:18:59.258426 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47) complete. Timing: real 0.049s	user 0.018s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14470,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:59.258916 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47): perf score=2.188937
I20260812 06:18:59.269584 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4041,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:59.270236 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling MajorDeltaCompactionOp(33781891b3e04535829fb030f881db47): perf score=1.000000
I20260812 06:18:59.418174 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: MajorDeltaCompactionOp(33781891b3e04535829fb030f881db47) complete. Timing: real 0.148s	user 0.098s	sys 0.049s 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":895,"lbm_read_time_us":11541,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24334,"lbm_writes_lt_1ms":443,"mutex_wait_us":264,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9216,"update_count":2000}
I20260812 06:18:59.418774 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47): perf score=10.126437
I20260812 06:18:59.461728 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47) complete. Timing: real 0.043s	user 0.034s	sys 0.000s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15473,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:59.462188 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47): perf score=2.188937
I20260812 06:18:59.472261 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3869,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:59.473018 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling MajorDeltaCompactionOp(33781891b3e04535829fb030f881db47): perf score=1.000000
I20260812 06:18:59.596057 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: MajorDeltaCompactionOp(33781891b3e04535829fb030f881db47) complete. Timing: real 0.123s	user 0.098s	sys 0.025s 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":1015,"lbm_read_time_us":7491,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24918,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:59.596527 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47): perf score=10.126437
I20260812 06:18:59.638751 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47) complete. Timing: real 0.042s	user 0.021s	sys 0.010s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14761,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:59.639230 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47): perf score=2.188937
I20260812 06:18:59.649394 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3849,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:59.650029 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling FlushMRSOp(33781891b3e04535829fb030f881db47): perf score=1.000000
I20260812 06:18:59.682058 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: FlushMRSOp(33781891b3e04535829fb030f881db47) complete. Timing: real 0.032s	user 0.029s	sys 0.001s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":68,"dirs.run_cpu_time_us":278,"dirs.run_wall_time_us":1292,"drs_written":1,"lbm_read_time_us":92,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1559,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:59.682852 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling LogGCOp(33781891b3e04535829fb030f881db47): free 112239264 bytes of WAL
I20260812 06:18:59.683063 11092 log_reader.cc:385] T 33781891b3e04535829fb030f881db47: removed 11 log segments from log reader
I20260812 06:18:59.683125 11092 log.cc:1079] T 33781891b3e04535829fb030f881db47 P 0219890e41ee4068925481d81e10ff00: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/33781891b3e04535829fb030f881db47/wal-000000003 (ops 12-16)
I20260812 06:18:59.683176 11092 log.cc:1079] T 33781891b3e04535829fb030f881db47 P 0219890e41ee4068925481d81e10ff00: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/33781891b3e04535829fb030f881db47/wal-000000004 (ops 17-21)
I20260812 06:18:59.683234 11092 log.cc:1079] T 33781891b3e04535829fb030f881db47 P 0219890e41ee4068925481d81e10ff00: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/33781891b3e04535829fb030f881db47/wal-000000005 (ops 22-26)
I20260812 06:18:59.683276 11092 log.cc:1079] T 33781891b3e04535829fb030f881db47 P 0219890e41ee4068925481d81e10ff00: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/33781891b3e04535829fb030f881db47/wal-000000006 (ops 27-31)
I20260812 06:18:59.683314 11092 log.cc:1079] T 33781891b3e04535829fb030f881db47 P 0219890e41ee4068925481d81e10ff00: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/33781891b3e04535829fb030f881db47/wal-000000007 (ops 32-36)
I20260812 06:18:59.683353 11092 log.cc:1079] T 33781891b3e04535829fb030f881db47 P 0219890e41ee4068925481d81e10ff00: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/33781891b3e04535829fb030f881db47/wal-000000008 (ops 37-40)
I20260812 06:18:59.683390 11092 log.cc:1079] T 33781891b3e04535829fb030f881db47 P 0219890e41ee4068925481d81e10ff00: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/33781891b3e04535829fb030f881db47/wal-000000009 (ops 41-45)
I20260812 06:18:59.683426 11092 log.cc:1079] T 33781891b3e04535829fb030f881db47 P 0219890e41ee4068925481d81e10ff00: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/33781891b3e04535829fb030f881db47/wal-000000010 (ops 46-50)
I20260812 06:18:59.683463 11092 log.cc:1079] T 33781891b3e04535829fb030f881db47 P 0219890e41ee4068925481d81e10ff00: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/33781891b3e04535829fb030f881db47/wal-000000011 (ops 51-55)
I20260812 06:18:59.683501 11092 log.cc:1079] T 33781891b3e04535829fb030f881db47 P 0219890e41ee4068925481d81e10ff00: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/33781891b3e04535829fb030f881db47/wal-000000012 (ops 56-60)
I20260812 06:18:59.683537 11092 log.cc:1079] T 33781891b3e04535829fb030f881db47 P 0219890e41ee4068925481d81e10ff00: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/33781891b3e04535829fb030f881db47/wal-000000013 (ops 61-65)
I20260812 06:18:59.707000 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: LogGCOp(33781891b3e04535829fb030f881db47) complete. Timing: real 0.024s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:18:59.707424 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling UndoDeltaBlockGCOp(33781891b3e04535829fb030f881db47): 462 bytes on disk
I20260812 06:18:59.707996 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: UndoDeltaBlockGCOp(33781891b3e04535829fb030f881db47) 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:59.708482 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47): perf score=4.173312
I20260812 06:18:59.725723 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47) complete. Timing: real 0.017s	user 0.015s	sys 0.000s Metrics: {"bytes_written":5497488,"delete_count":0,"lbm_write_time_us":7146,"lbm_writes_lt_1ms":137,"reinsert_count":0,"update_count":670}
I20260812 06:18:59.726140 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47): perf score=1.196750
I20260812 06:18:59.734145 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47) complete. Timing: real 0.008s	user 0.006s	sys 0.000s Metrics: {"bytes_written":2707805,"delete_count":0,"lbm_write_time_us":2503,"lbm_writes_lt_1ms":69,"reinsert_count":0,"update_count":330}
I20260812 06:18:59.734570 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling MajorDeltaCompactionOp(33781891b3e04535829fb030f881db47): perf score=1.000000
I20260812 06:18:59.907142 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: MajorDeltaCompactionOp(33781891b3e04535829fb030f881db47) complete. Timing: real 0.172s	user 0.158s	sys 0.008s 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":684,"lbm_read_time_us":12532,"lbm_reads_lt_1ms":674,"lbm_write_time_us":34478,"lbm_writes_lt_1ms":643,"mutex_wait_us":23,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":47232,"thread_start_us":80,"threads_started":1,"update_count":3000}
I20260812 06:18:59.907793 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47): perf score=14.095187
I20260812 06:18:59.962337 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47) complete. Timing: real 0.054s	user 0.034s	sys 0.017s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23294,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:59.962841 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47): perf score=2.188937
I20260812 06:18:59.980420 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47) complete. Timing: real 0.017s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4612,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:59.981132 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling MajorDeltaCompactionOp(33781891b3e04535829fb030f881db47): perf score=1.000000
I20260812 06:19:00.120013 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: MajorDeltaCompactionOp(33781891b3e04535829fb030f881db47) complete. Timing: real 0.139s	user 0.104s	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":759,"lbm_read_time_us":8203,"lbm_reads_lt_1ms":564,"lbm_write_time_us":27099,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9344,"update_count":2500}
I20260812 06:19:00.120697 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47): perf score=14.095187
I20260812 06:19:00.175566 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47) complete. Timing: real 0.055s	user 0.032s	sys 0.019s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":26185,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:19:00.176121 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47): perf score=2.188937
I20260812 06:19:00.187515 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4354,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:00.188019 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling MajorDeltaCompactionOp(33781891b3e04535829fb030f881db47): perf score=1.000000
I20260812 06:19:00.341202 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: MajorDeltaCompactionOp(33781891b3e04535829fb030f881db47) complete. Timing: real 0.153s	user 0.099s	sys 0.043s 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":589,"lbm_read_time_us":10223,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27183,"lbm_writes_lt_1ms":543,"mutex_wait_us":272,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":20736,"update_count":2500}
I20260812 06:19:00.341842 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47): perf score=14.095187
I20260812 06:19:00.392617 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47) complete. Timing: real 0.051s	user 0.032s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19822,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:00.393224 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling MajorDeltaCompactionOp(33781891b3e04535829fb030f881db47): perf score=1.000000
I20260812 06:19:00.534808 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: MajorDeltaCompactionOp(33781891b3e04535829fb030f881db47) complete. Timing: real 0.141s	user 0.085s	sys 0.052s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672157,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":563,"lbm_read_time_us":9204,"lbm_reads_lt_1ms":463,"lbm_write_time_us":22576,"lbm_writes_lt_1ms":443,"mutex_wait_us":327,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8448,"update_count":2000}
I20260812 06:19:00.535563 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47): perf score=14.095187
I20260812 06:19:00.580952 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47) complete. Timing: real 0.045s	user 0.026s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17193,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:00.581511 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47): perf score=2.188937
I20260812 06:19:00.592212 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47) complete. Timing: real 0.010s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3878,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:00.592695 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling MajorDeltaCompactionOp(33781891b3e04535829fb030f881db47): perf score=1.000000
I20260812 06:19:00.766952 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: MajorDeltaCompactionOp(33781891b3e04535829fb030f881db47) complete. Timing: real 0.174s	user 0.115s	sys 0.049s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":147,"lbm_read_time_us":9418,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28535,"lbm_writes_lt_1ms":543,"mutex_wait_us":2,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7936,"update_count":2500}
I20260812 06:19:00.767730 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47): perf score=14.095187
I20260812 06:19:00.821009 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47) complete. Timing: real 0.053s	user 0.023s	sys 0.028s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":24346,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:19:00.821504 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47): perf score=2.188937
I20260812 06:19:00.833199 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4371,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:00.833700 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling MajorDeltaCompactionOp(33781891b3e04535829fb030f881db47): perf score=1.000000
I20260812 06:19:00.993850 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: MajorDeltaCompactionOp(33781891b3e04535829fb030f881db47) complete. Timing: real 0.160s	user 0.112s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":118,"lbm_read_time_us":8672,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31688,"lbm_writes_lt_1ms":543,"mutex_wait_us":47,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8192,"update_count":2500}
I20260812 06:19:00.994508 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47): perf score=14.095187
I20260812 06:19:01.043460 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47) complete. Timing: real 0.049s	user 0.019s	sys 0.019s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":18367,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:01.044080 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47): perf score=2.188937
I20260812 06:19:01.059338 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47) complete. Timing: real 0.015s	user 0.000s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5852,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:01.060045 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling FlushMRSOp(33781891b3e04535829fb030f881db47): perf score=1.000000
I20260812 06:19:01.094060 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: FlushMRSOp(33781891b3e04535829fb030f881db47) complete. Timing: real 0.034s	user 0.028s	sys 0.004s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":56,"dirs.run_cpu_time_us":228,"dirs.run_wall_time_us":1276,"drs_written":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2035,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:01.094808 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling LogGCOp(33781891b3e04535829fb030f881db47): free 129320563 bytes of WAL
I20260812 06:19:01.095038 11092 log_reader.cc:385] T 33781891b3e04535829fb030f881db47: removed 13 log segments from log reader
I20260812 06:19:01.095085 11092 log.cc:1079] T 33781891b3e04535829fb030f881db47 P 0219890e41ee4068925481d81e10ff00: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/33781891b3e04535829fb030f881db47/wal-000000014 (ops 66-70)
I20260812 06:19:01.095113 11092 log.cc:1079] T 33781891b3e04535829fb030f881db47 P 0219890e41ee4068925481d81e10ff00: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/33781891b3e04535829fb030f881db47/wal-000000015 (ops 71-74)
I20260812 06:19:01.095176 11092 log.cc:1079] T 33781891b3e04535829fb030f881db47 P 0219890e41ee4068925481d81e10ff00: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/33781891b3e04535829fb030f881db47/wal-000000016 (ops 75-79)
I20260812 06:19:01.095224 11092 log.cc:1079] T 33781891b3e04535829fb030f881db47 P 0219890e41ee4068925481d81e10ff00: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/33781891b3e04535829fb030f881db47/wal-000000017 (ops 80-84)
I20260812 06:19:01.095268 11092 log.cc:1079] T 33781891b3e04535829fb030f881db47 P 0219890e41ee4068925481d81e10ff00: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/33781891b3e04535829fb030f881db47/wal-000000018 (ops 85-89)
I20260812 06:19:01.095328 11092 log.cc:1079] T 33781891b3e04535829fb030f881db47 P 0219890e41ee4068925481d81e10ff00: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/33781891b3e04535829fb030f881db47/wal-000000019 (ops 90-94)
I20260812 06:19:01.095368 11092 log.cc:1079] T 33781891b3e04535829fb030f881db47 P 0219890e41ee4068925481d81e10ff00: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/33781891b3e04535829fb030f881db47/wal-000000020 (ops 95-99)
I20260812 06:19:01.095409 11092 log.cc:1079] T 33781891b3e04535829fb030f881db47 P 0219890e41ee4068925481d81e10ff00: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/33781891b3e04535829fb030f881db47/wal-000000021 (ops 100-104)
I20260812 06:19:01.095451 11092 log.cc:1079] T 33781891b3e04535829fb030f881db47 P 0219890e41ee4068925481d81e10ff00: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/33781891b3e04535829fb030f881db47/wal-000000022 (ops 105-109)
I20260812 06:19:01.095492 11092 log.cc:1079] T 33781891b3e04535829fb030f881db47 P 0219890e41ee4068925481d81e10ff00: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/33781891b3e04535829fb030f881db47/wal-000000023 (ops 110-114)
I20260812 06:19:01.095532 11092 log.cc:1079] T 33781891b3e04535829fb030f881db47 P 0219890e41ee4068925481d81e10ff00: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/33781891b3e04535829fb030f881db47/wal-000000024 (ops 115-118)
I20260812 06:19:01.095572 11092 log.cc:1079] T 33781891b3e04535829fb030f881db47 P 0219890e41ee4068925481d81e10ff00: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/33781891b3e04535829fb030f881db47/wal-000000025 (ops 119-123)
I20260812 06:19:01.095613 11092 log.cc:1079] T 33781891b3e04535829fb030f881db47 P 0219890e41ee4068925481d81e10ff00: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/33781891b3e04535829fb030f881db47/wal-000000026 (ops 124-128)
I20260812 06:19:01.120126 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: LogGCOp(33781891b3e04535829fb030f881db47) complete. Timing: real 0.025s	user 0.002s	sys 0.023s Metrics: {}
I20260812 06:19:01.120594 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling UndoDeltaBlockGCOp(33781891b3e04535829fb030f881db47): 482 bytes on disk
I20260812 06:19:01.121006 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: UndoDeltaBlockGCOp(33781891b3e04535829fb030f881db47) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4}
I20260812 06:19:01.121618 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47): perf score=3.181125
I20260812 06:19:01.141880 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47) complete. Timing: real 0.020s	user 0.002s	sys 0.015s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4623,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:01.142403 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47): perf score=2.188937
I20260812 06:19:01.157150 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47) complete. Timing: real 0.015s	user 0.008s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5565,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:01.157758 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling MajorDeltaCompactionOp(33781891b3e04535829fb030f881db47): perf score=1.000000
I20260812 06:19:01.367915 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: MajorDeltaCompactionOp(33781891b3e04535829fb030f881db47) complete. Timing: real 0.210s	user 0.128s	sys 0.081s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979736,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":699,"lbm_read_time_us":15671,"lbm_reads_lt_1ms":774,"lbm_write_time_us":36681,"lbm_writes_lt_1ms":743,"mutex_wait_us":101,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":14976,"thread_start_us":88,"threads_started":1,"update_count":3500}
I20260812 06:19:01.368842 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47): perf score=14.095187
I20260812 06:19:01.425293 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47) complete. Timing: real 0.056s	user 0.040s	sys 0.012s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23512,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:01.425837 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47): perf score=2.188937
I20260812 06:19:01.436892 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4138,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:01.437325 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling MajorDeltaCompactionOp(33781891b3e04535829fb030f881db47): perf score=1.000000
I20260812 06:19:01.622128 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: MajorDeltaCompactionOp(33781891b3e04535829fb030f881db47) complete. Timing: real 0.185s	user 0.112s	sys 0.073s 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":159,"lbm_read_time_us":14124,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31336,"lbm_writes_lt_1ms":543,"mutex_wait_us":41,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8448,"update_count":2500}
I20260812 06:19:01.622820 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47): perf score=10.126437
I20260812 06:19:01.659848 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47) complete. Timing: real 0.037s	user 0.025s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16079,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:01.660444 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47): perf score=2.188937
I20260812 06:19:01.681313 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47) complete. Timing: real 0.021s	user 0.001s	sys 0.018s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6247,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:01.681810 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling MajorDeltaCompactionOp(33781891b3e04535829fb030f881db47): perf score=1.000000
I20260812 06:19:01.837538 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: MajorDeltaCompactionOp(33781891b3e04535829fb030f881db47) complete. Timing: real 0.156s	user 0.118s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":625,"lbm_read_time_us":9467,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26088,"lbm_writes_lt_1ms":443,"mutex_wait_us":272,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:01.838052 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47): perf score=14.095187
I20260812 06:19:01.890837 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47) complete. Timing: real 0.053s	user 0.032s	sys 0.012s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":22548,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:01.891336 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47): perf score=2.188937
I20260812 06:19:01.901558 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3877,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:01.902281 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling MajorDeltaCompactionOp(33781891b3e04535829fb030f881db47): perf score=1.000000
I20260812 06:19:02.058166 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: MajorDeltaCompactionOp(33781891b3e04535829fb030f881db47) complete. Timing: real 0.156s	user 0.111s	sys 0.032s 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":253,"lbm_read_time_us":11342,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27766,"lbm_writes_lt_1ms":543,"mutex_wait_us":32,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12928,"update_count":2500}
I20260812 06:19:02.058908 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47): perf score=14.095187
I20260812 06:19:02.111805 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47) complete. Timing: real 0.053s	user 0.034s	sys 0.016s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":22238,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:02.112308 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47): perf score=2.188937
I20260812 06:19:02.123025 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4185,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:02.123741 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling MajorDeltaCompactionOp(33781891b3e04535829fb030f881db47): perf score=1.000000
I20260812 06:19:02.272945 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: MajorDeltaCompactionOp(33781891b3e04535829fb030f881db47) complete. Timing: real 0.149s	user 0.116s	sys 0.033s 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":445,"lbm_read_time_us":10908,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30838,"lbm_writes_lt_1ms":543,"mutex_wait_us":49,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14848,"update_count":2500}
I20260812 06:19:02.273555 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47): perf score=11.118625
I20260812 06:19:02.308590 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47) complete. Timing: real 0.035s	user 0.022s	sys 0.011s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":14807,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:02.309132 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47): perf score=2.188937
I20260812 06:19:02.323328 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5147,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:02.323882 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling MajorDeltaCompactionOp(33781891b3e04535829fb030f881db47): perf score=1.000000
I20260812 06:19:02.441334 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: MajorDeltaCompactionOp(33781891b3e04535829fb030f881db47) complete. Timing: real 0.117s	user 0.076s	sys 0.041s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672269,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":929,"lbm_read_time_us":6984,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23326,"lbm_writes_lt_1ms":443,"mutex_wait_us":270,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:02.442085 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47): perf score=10.126437
I20260812 06:19:02.489368 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47) complete. Timing: real 0.046s	user 0.013s	sys 0.031s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16310,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:02.490162 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47): perf score=2.188937
I20260812 06:19:02.504192 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47) complete. Timing: real 0.014s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5618,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:02.504740 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling FlushMRSOp(33781891b3e04535829fb030f881db47): perf score=1.000000
I20260812 06:19:02.536195 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: FlushMRSOp(33781891b3e04535829fb030f881db47) complete. Timing: real 0.031s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1234477,"cfile_init":1,"dirs.queue_time_us":72,"dirs.run_cpu_time_us":236,"dirs.run_wall_time_us":1158,"drs_written":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2041,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:02.536861 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling LogGCOp(33781891b3e04535829fb030f881db47): free 123804445 bytes of WAL
I20260812 06:19:02.537092 11092 log_reader.cc:385] T 33781891b3e04535829fb030f881db47: removed 12 log segments from log reader
I20260812 06:19:02.537159 11092 log.cc:1079] T 33781891b3e04535829fb030f881db47 P 0219890e41ee4068925481d81e10ff00: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/33781891b3e04535829fb030f881db47/wal-000000027 (ops 129-133)
I20260812 06:19:02.537213 11092 log.cc:1079] T 33781891b3e04535829fb030f881db47 P 0219890e41ee4068925481d81e10ff00: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/33781891b3e04535829fb030f881db47/wal-000000028 (ops 134-138)
I20260812 06:19:02.537279 11092 log.cc:1079] T 33781891b3e04535829fb030f881db47 P 0219890e41ee4068925481d81e10ff00: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/33781891b3e04535829fb030f881db47/wal-000000029 (ops 139-143)
I20260812 06:19:02.537321 11092 log.cc:1079] T 33781891b3e04535829fb030f881db47 P 0219890e41ee4068925481d81e10ff00: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/33781891b3e04535829fb030f881db47/wal-000000030 (ops 144-148)
I20260812 06:19:02.537361 11092 log.cc:1079] T 33781891b3e04535829fb030f881db47 P 0219890e41ee4068925481d81e10ff00: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/33781891b3e04535829fb030f881db47/wal-000000031 (ops 149-152)
I20260812 06:19:02.537401 11092 log.cc:1079] T 33781891b3e04535829fb030f881db47 P 0219890e41ee4068925481d81e10ff00: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/33781891b3e04535829fb030f881db47/wal-000000032 (ops 153-157)
I20260812 06:19:02.537439 11092 log.cc:1079] T 33781891b3e04535829fb030f881db47 P 0219890e41ee4068925481d81e10ff00: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/33781891b3e04535829fb030f881db47/wal-000000033 (ops 158-162)
I20260812 06:19:02.537477 11092 log.cc:1079] T 33781891b3e04535829fb030f881db47 P 0219890e41ee4068925481d81e10ff00: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/33781891b3e04535829fb030f881db47/wal-000000034 (ops 163-167)
I20260812 06:19:02.537518 11092 log.cc:1079] T 33781891b3e04535829fb030f881db47 P 0219890e41ee4068925481d81e10ff00: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/33781891b3e04535829fb030f881db47/wal-000000035 (ops 168-172)
I20260812 06:19:02.537555 11092 log.cc:1079] T 33781891b3e04535829fb030f881db47 P 0219890e41ee4068925481d81e10ff00: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/33781891b3e04535829fb030f881db47/wal-000000036 (ops 173-177)
I20260812 06:19:02.537593 11092 log.cc:1079] T 33781891b3e04535829fb030f881db47 P 0219890e41ee4068925481d81e10ff00: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/33781891b3e04535829fb030f881db47/wal-000000037 (ops 178-182)
I20260812 06:19:02.537632 11092 log.cc:1079] T 33781891b3e04535829fb030f881db47 P 0219890e41ee4068925481d81e10ff00: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/33781891b3e04535829fb030f881db47/wal-000000038 (ops 183-186)
I20260812 06:19:02.563427 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: LogGCOp(33781891b3e04535829fb030f881db47) complete. Timing: real 0.026s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:19:02.563988 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling UndoDeltaBlockGCOp(33781891b3e04535829fb030f881db47): 472 bytes on disk
I20260812 06:19:02.564554 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: UndoDeltaBlockGCOp(33781891b3e04535829fb030f881db47) 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:19:02.566107 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47): perf score=5.165500
I20260812 06:19:02.585187 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47) complete. Timing: real 0.019s	user 0.005s	sys 0.012s Metrics: {"bytes_written":6482066,"delete_count":0,"lbm_write_time_us":8021,"lbm_writes_lt_1ms":161,"reinsert_count":0,"update_count":790}
I20260812 06:19:02.585655 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling LogGCOp(33781891b3e04535829fb030f881db47): free 8767138 bytes of WAL
I20260812 06:19:02.585906 11092 log_reader.cc:385] T 33781891b3e04535829fb030f881db47: removed 1 log segments from log reader
I20260812 06:19:02.585956 11092 log.cc:1079] T 33781891b3e04535829fb030f881db47 P 0219890e41ee4068925481d81e10ff00: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/33781891b3e04535829fb030f881db47/wal-000000039 (ops 187-191)
I20260812 06:19:02.587806 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: LogGCOp(33781891b3e04535829fb030f881db47) complete. Timing: real 0.002s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:19:02.588127 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47): perf score=1.000000
I20260812 06:19:02.595000 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47) complete. Timing: real 0.007s	user 0.000s	sys 0.005s Metrics: {"bytes_written":1723202,"delete_count":0,"lbm_write_time_us":2116,"lbm_writes_lt_1ms":45,"reinsert_count":0,"update_count":210}
I20260812 06:19:02.595525 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling MajorDeltaCompactionOp(33781891b3e04535829fb030f881db47): perf score=1.000000
I20260812 06:19:02.785713 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: MajorDeltaCompactionOp(33781891b3e04535829fb030f881db47) complete. Timing: real 0.190s	user 0.130s	sys 0.060s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877283,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1000,"lbm_read_time_us":12733,"lbm_reads_lt_1ms":674,"lbm_write_time_us":32284,"lbm_writes_lt_1ms":643,"mutex_wait_us":340,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":29568,"thread_start_us":94,"threads_started":1,"update_count":3000}
I20260812 06:19:02.786319 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47): perf score=14.095187
I20260812 06:19:02.846182 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: FlushDeltaMemStoresOp(33781891b3e04535829fb030f881db47) complete. Timing: real 0.060s	user 0.023s	sys 0.027s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":23992,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:02.846659 11152 maintenance_manager.cc:419] P 0219890e41ee4068925481d81e10ff00: Scheduling MajorDeltaCompactionOp(33781891b3e04535829fb030f881db47): perf score=1.000000
I20260812 06:19:02.857216 10991 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.711s	user 1.817s	sys 0.110s
I20260812 06:19:02.934358 10991 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.077s	user 0.001s	sys 0.000s
I20260812 06:19:02.935053 10991 tablet_server.cc:179] TabletServer@127.10.187.193:0 shutting down...
I20260812 06:19:02.983929 11092 maintenance_manager.cc:643] P 0219890e41ee4068925481d81e10ff00: MajorDeltaCompactionOp(33781891b3e04535829fb030f881db47) complete. Timing: real 0.137s	user 0.079s	sys 0.058s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672156,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":548,"lbm_read_time_us":9986,"lbm_reads_lt_1ms":459,"lbm_write_time_us":23448,"lbm_writes_lt_1ms":443,"mutex_wait_us":58,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":59392,"update_count":2000}
I20260812 06:19:02.984826 10991 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:02.985272 10991 tablet_replica.cc:333] T 33781891b3e04535829fb030f881db47 P 0219890e41ee4068925481d81e10ff00: stopping tablet replica
I20260812 06:19:02.985505 10991 raft_consensus.cc:2243] T 33781891b3e04535829fb030f881db47 P 0219890e41ee4068925481d81e10ff00 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:02.985735 10991 raft_consensus.cc:2272] T 33781891b3e04535829fb030f881db47 P 0219890e41ee4068925481d81e10ff00 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:03.002475 10991 tablet_server.cc:196] TabletServer@127.10.187.193:0 shutdown complete.
I20260812 06:19:03.023181 10991 master.cc:562] Master@127.10.187.254:38721 shutting down...
I20260812 06:19:03.026953 10991 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 5641d653355447018cb617a8de8c6b9b [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:03.027163 10991 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 5641d653355447018cb617a8de8c6b9b [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:03.027254 10991 tablet_replica.cc:333] T 00000000000000000000000000000000 P 5641d653355447018cb617a8de8c6b9b: stopping tablet replica
I20260812 06:19:03.039625 10991 master.cc:584] Master@127.10.187.254:38721 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5248 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:19:03.122545 10991 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.10.187.254:40309
I20260812 06:19:03.122908 10991 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:03.124953 11183 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:03.124989 11182 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:03.124985 10991 server_base.cc:1061] running on GCE node
W20260812 06:19:03.125001 11185 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:03.125365 10991 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:03.125412 10991 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:03.125428 10991 hybrid_clock.cc:648] HybridClock initialized: now 1786515543125428 us; error 0 us; skew 500 ppm
I20260812 06:19:03.126345 10991 webserver.cc:533] Webserver started at http://127.10.187.254:44539/ using document root <none> and password file <none>
I20260812 06:19:03.126533 10991 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:03.126609 10991 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:03.126693 10991 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:03.127112 10991 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537863371-10991-0/minicluster-data/master-0-root/instance:
uuid: "2e1e329b65564e4bbc4a2b9fec456c0b"
format_stamp: "Formatted at 2026-08-12 06:19:03 on dist-test-slave-bxbt"
I20260812 06:19:03.128818 10991 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:19:03.129829 11190 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:03.130107 10991 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:19:03.130177 10991 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537863371-10991-0/minicluster-data/master-0-root
uuid: "2e1e329b65564e4bbc4a2b9fec456c0b"
format_stamp: "Formatted at 2026-08-12 06:19:03 on dist-test-slave-bxbt"
I20260812 06:19:03.130280 10991 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537863371-10991-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537863371-10991-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537863371-10991-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:03.146472 10991 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:03.146960 10991 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:03.151575 10991 rpc_server.cc:307] RPC server started. Bound to: 127.10.187.254:40309
I20260812 06:19:03.153250 11242 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.10.187.254:40309 every 8 connection(s)
I20260812 06:19:03.153807 11243 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:03.168159 11243 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 2e1e329b65564e4bbc4a2b9fec456c0b: Bootstrap starting.
I20260812 06:19:03.169430 11243 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 2e1e329b65564e4bbc4a2b9fec456c0b: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:03.171057 11243 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 2e1e329b65564e4bbc4a2b9fec456c0b: No bootstrap required, opened a new log
I20260812 06:19:03.171718 11243 raft_consensus.cc:359] T 00000000000000000000000000000000 P 2e1e329b65564e4bbc4a2b9fec456c0b [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2e1e329b65564e4bbc4a2b9fec456c0b" member_type: VOTER }
I20260812 06:19:03.171905 11243 raft_consensus.cc:385] T 00000000000000000000000000000000 P 2e1e329b65564e4bbc4a2b9fec456c0b [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:03.171947 11243 raft_consensus.cc:740] T 00000000000000000000000000000000 P 2e1e329b65564e4bbc4a2b9fec456c0b [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 2e1e329b65564e4bbc4a2b9fec456c0b, State: Initialized, Role: FOLLOWER
I20260812 06:19:03.172132 11243 consensus_queue.cc:260] T 00000000000000000000000000000000 P 2e1e329b65564e4bbc4a2b9fec456c0b [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: "2e1e329b65564e4bbc4a2b9fec456c0b" member_type: VOTER }
I20260812 06:19:03.172235 11243 raft_consensus.cc:399] T 00000000000000000000000000000000 P 2e1e329b65564e4bbc4a2b9fec456c0b [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:03.172288 11243 raft_consensus.cc:493] T 00000000000000000000000000000000 P 2e1e329b65564e4bbc4a2b9fec456c0b [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:03.172343 11243 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 2e1e329b65564e4bbc4a2b9fec456c0b [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:03.173324 11243 raft_consensus.cc:515] T 00000000000000000000000000000000 P 2e1e329b65564e4bbc4a2b9fec456c0b [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2e1e329b65564e4bbc4a2b9fec456c0b" member_type: VOTER }
I20260812 06:19:03.173492 11243 leader_election.cc:304] T 00000000000000000000000000000000 P 2e1e329b65564e4bbc4a2b9fec456c0b [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: 2e1e329b65564e4bbc4a2b9fec456c0b; no voters: 
I20260812 06:19:03.173725 11243 leader_election.cc:290] T 00000000000000000000000000000000 P 2e1e329b65564e4bbc4a2b9fec456c0b [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:03.173931 11246 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 2e1e329b65564e4bbc4a2b9fec456c0b [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:03.174223 11246 raft_consensus.cc:697] T 00000000000000000000000000000000 P 2e1e329b65564e4bbc4a2b9fec456c0b [term 1 LEADER]: Becoming Leader. State: Replica: 2e1e329b65564e4bbc4a2b9fec456c0b, State: Running, Role: LEADER
I20260812 06:19:03.174309 11243 sys_catalog.cc:565] T 00000000000000000000000000000000 P 2e1e329b65564e4bbc4a2b9fec456c0b [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:03.174405 11246 consensus_queue.cc:237] T 00000000000000000000000000000000 P 2e1e329b65564e4bbc4a2b9fec456c0b [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: "2e1e329b65564e4bbc4a2b9fec456c0b" member_type: VOTER }
I20260812 06:19:03.174913 11248 sys_catalog.cc:455] T 00000000000000000000000000000000 P 2e1e329b65564e4bbc4a2b9fec456c0b [sys.catalog]: SysCatalogTable state changed. Reason: New leader 2e1e329b65564e4bbc4a2b9fec456c0b. Latest consensus state: current_term: 1 leader_uuid: "2e1e329b65564e4bbc4a2b9fec456c0b" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2e1e329b65564e4bbc4a2b9fec456c0b" member_type: VOTER } }
I20260812 06:19:03.175017 11248 sys_catalog.cc:458] T 00000000000000000000000000000000 P 2e1e329b65564e4bbc4a2b9fec456c0b [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:03.174899 11247 sys_catalog.cc:455] T 00000000000000000000000000000000 P 2e1e329b65564e4bbc4a2b9fec456c0b [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "2e1e329b65564e4bbc4a2b9fec456c0b" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2e1e329b65564e4bbc4a2b9fec456c0b" member_type: VOTER } }
I20260812 06:19:03.175156 11247 sys_catalog.cc:458] T 00000000000000000000000000000000 P 2e1e329b65564e4bbc4a2b9fec456c0b [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:03.175359 11254 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:03.176263 11254 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:03.176497 10991 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:03.178462 11254 catalog_manager.cc:1383] Generated new cluster ID: db7afbab0ada4bdfbdfec234c533f320
I20260812 06:19:03.178526 11254 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:03.190168 11254 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:03.190796 11254 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:03.196548 11254 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 2e1e329b65564e4bbc4a2b9fec456c0b: Generated new TSK 0
I20260812 06:19:03.196784 11254 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:03.208989 10991 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:03.211179 11265 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:03.211283 10991 server_base.cc:1061] running on GCE node
W20260812 06:19:03.211216 11264 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:03.211362 11267 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:03.211608 10991 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:03.211678 10991 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:03.211730 10991 hybrid_clock.cc:648] HybridClock initialized: now 1786515543211729 us; error 0 us; skew 500 ppm
I20260812 06:19:03.212738 10991 webserver.cc:533] Webserver started at http://127.10.187.193:44501/ using document root <none> and password file <none>
I20260812 06:19:03.212971 10991 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:03.213052 10991 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:03.213135 10991 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:03.213552 10991 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537863371-10991-0/minicluster-data/ts-0-root/instance:
uuid: "0db5c121c6434ac197d89fd654142ba1"
format_stamp: "Formatted at 2026-08-12 06:19:03 on dist-test-slave-bxbt"
I20260812 06:19:03.215128 10991 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:19:03.216338 11272 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:03.216619 10991 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.000s
I20260812 06:19:03.216725 10991 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537863371-10991-0/minicluster-data/ts-0-root
uuid: "0db5c121c6434ac197d89fd654142ba1"
format_stamp: "Formatted at 2026-08-12 06:19:03 on dist-test-slave-bxbt"
I20260812 06:19:03.216868 10991 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537863371-10991-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537863371-10991-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537863371-10991-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:03.227234 10991 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:03.227821 10991 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:03.228209 10991 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:03.228734 10991 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:03.228809 10991 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:03.228874 10991 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:03.228931 10991 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:03.234098 10991 rpc_server.cc:307] RPC server started. Bound to: 127.10.187.193:43545
I20260812 06:19:03.234127 11335 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.10.187.193:43545 every 8 connection(s)
I20260812 06:19:03.242427 11336 heartbeater.cc:344] Connected to a master server at 127.10.187.254:40309
I20260812 06:19:03.242558 11336 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:03.242770 11336 heartbeater.cc:507] Master 127.10.187.254:40309 requested a full tablet report, sending...
I20260812 06:19:03.243407 11207 ts_manager.cc:194] Registered new tserver with Master: 0db5c121c6434ac197d89fd654142ba1 (127.10.187.193:43545)
I20260812 06:19:03.243492 10991 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.008902838s
I20260812 06:19:03.244491 11207 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:42130
I20260812 06:19:03.250926 11207 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:42142:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:03.260294 11300 tablet_service.cc:1511] Processing CreateTablet for tablet 7a192204c88340e1820ae6a2c1e7948d (DEFAULT_TABLE table=heavy-update-compaction-test [id=89b9e49ab1c84931b9bc4f382c28739c]), partition=
I20260812 06:19:03.260589 11300 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 7a192204c88340e1820ae6a2c1e7948d. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:03.262645 11348 tablet_bootstrap.cc:492] T 7a192204c88340e1820ae6a2c1e7948d P 0db5c121c6434ac197d89fd654142ba1: Bootstrap starting.
I20260812 06:19:03.263526 11348 tablet_bootstrap.cc:654] T 7a192204c88340e1820ae6a2c1e7948d P 0db5c121c6434ac197d89fd654142ba1: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:03.264859 11348 tablet_bootstrap.cc:492] T 7a192204c88340e1820ae6a2c1e7948d P 0db5c121c6434ac197d89fd654142ba1: No bootstrap required, opened a new log
I20260812 06:19:03.264986 11348 ts_tablet_manager.cc:1403] T 7a192204c88340e1820ae6a2c1e7948d P 0db5c121c6434ac197d89fd654142ba1: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:03.265527 11348 raft_consensus.cc:359] T 7a192204c88340e1820ae6a2c1e7948d P 0db5c121c6434ac197d89fd654142ba1 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0db5c121c6434ac197d89fd654142ba1" member_type: VOTER last_known_addr { host: "127.10.187.193" port: 43545 } }
I20260812 06:19:03.265621 11348 raft_consensus.cc:385] T 7a192204c88340e1820ae6a2c1e7948d P 0db5c121c6434ac197d89fd654142ba1 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:03.265643 11348 raft_consensus.cc:740] T 7a192204c88340e1820ae6a2c1e7948d P 0db5c121c6434ac197d89fd654142ba1 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 0db5c121c6434ac197d89fd654142ba1, State: Initialized, Role: FOLLOWER
I20260812 06:19:03.265815 11348 consensus_queue.cc:260] T 7a192204c88340e1820ae6a2c1e7948d P 0db5c121c6434ac197d89fd654142ba1 [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: "0db5c121c6434ac197d89fd654142ba1" member_type: VOTER last_known_addr { host: "127.10.187.193" port: 43545 } }
I20260812 06:19:03.265899 11348 raft_consensus.cc:399] T 7a192204c88340e1820ae6a2c1e7948d P 0db5c121c6434ac197d89fd654142ba1 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:03.265923 11348 raft_consensus.cc:493] T 7a192204c88340e1820ae6a2c1e7948d P 0db5c121c6434ac197d89fd654142ba1 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:03.265980 11348 raft_consensus.cc:3060] T 7a192204c88340e1820ae6a2c1e7948d P 0db5c121c6434ac197d89fd654142ba1 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:03.266757 11348 raft_consensus.cc:515] T 7a192204c88340e1820ae6a2c1e7948d P 0db5c121c6434ac197d89fd654142ba1 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0db5c121c6434ac197d89fd654142ba1" member_type: VOTER last_known_addr { host: "127.10.187.193" port: 43545 } }
I20260812 06:19:03.266877 11348 leader_election.cc:304] T 7a192204c88340e1820ae6a2c1e7948d P 0db5c121c6434ac197d89fd654142ba1 [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: 0db5c121c6434ac197d89fd654142ba1; no voters: 
I20260812 06:19:03.267141 11348 leader_election.cc:290] T 7a192204c88340e1820ae6a2c1e7948d P 0db5c121c6434ac197d89fd654142ba1 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:03.267311 11350 raft_consensus.cc:2804] T 7a192204c88340e1820ae6a2c1e7948d P 0db5c121c6434ac197d89fd654142ba1 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:03.267588 11348 ts_tablet_manager.cc:1434] T 7a192204c88340e1820ae6a2c1e7948d P 0db5c121c6434ac197d89fd654142ba1: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:19:03.267611 11336 heartbeater.cc:499] Master 127.10.187.254:40309 was elected leader, sending a full tablet report...
I20260812 06:19:03.267562 11350 raft_consensus.cc:697] T 7a192204c88340e1820ae6a2c1e7948d P 0db5c121c6434ac197d89fd654142ba1 [term 1 LEADER]: Becoming Leader. State: Replica: 0db5c121c6434ac197d89fd654142ba1, State: Running, Role: LEADER
I20260812 06:19:03.267894 11350 consensus_queue.cc:237] T 7a192204c88340e1820ae6a2c1e7948d P 0db5c121c6434ac197d89fd654142ba1 [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: "0db5c121c6434ac197d89fd654142ba1" member_type: VOTER last_known_addr { host: "127.10.187.193" port: 43545 } }
I20260812 06:19:03.269518 11207 catalog_manager.cc:5719] T 7a192204c88340e1820ae6a2c1e7948d P 0db5c121c6434ac197d89fd654142ba1 reported cstate change: term changed from 0 to 1, leader changed from <none> to 0db5c121c6434ac197d89fd654142ba1 (127.10.187.193). New cstate: current_term: 1 leader_uuid: "0db5c121c6434ac197d89fd654142ba1" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0db5c121c6434ac197d89fd654142ba1" member_type: VOTER last_known_addr { host: "127.10.187.193" port: 43545 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:03.332890 10991 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.056s	user 0.016s	sys 0.008s
I20260812 06:19:03.485141 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling FlushMRSOp(7a192204c88340e1820ae6a2c1e7948d): perf score=19.054940
I20260812 06:19:03.643572 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: FlushMRSOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.158s	user 0.130s	sys 0.024s Metrics: {"bytes_written":12717735,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":69,"dirs.run_cpu_time_us":229,"dirs.run_wall_time_us":878,"drs_written":1,"lbm_read_time_us":129,"lbm_reads_lt_1ms":4,"lbm_write_time_us":39845,"lbm_writes_lt_1ms":767,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1550}
I20260812 06:19:03.644431 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling LogGCOp(7a192204c88340e1820ae6a2c1e7948d): free 20743880 bytes of WAL
I20260812 06:19:03.644711 11277 log_reader.cc:385] T 7a192204c88340e1820ae6a2c1e7948d: removed 2 log segments from log reader
I20260812 06:19:03.644774 11277 log.cc:1079] T 7a192204c88340e1820ae6a2c1e7948d P 0db5c121c6434ac197d89fd654142ba1: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/7a192204c88340e1820ae6a2c1e7948d/wal-000000001 (ops 1-6)
I20260812 06:19:03.644815 11277 log.cc:1079] T 7a192204c88340e1820ae6a2c1e7948d P 0db5c121c6434ac197d89fd654142ba1: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/7a192204c88340e1820ae6a2c1e7948d/wal-000000002 (ops 7-11)
I20260812 06:19:03.650166 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: LogGCOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.006s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:19:03.650563 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling UndoDeltaBlockGCOp(7a192204c88340e1820ae6a2c1e7948d): 16411392 bytes on disk
I20260812 06:19:03.651072 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: UndoDeltaBlockGCOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":67,"lbm_reads_lt_1ms":4}
I20260812 06:19:03.651527 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d): perf score=2.188937
I20260812 06:19:03.674227 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.023s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4976,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:03.674664 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d): perf score=2.188937
I20260812 06:19:03.691264 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.016s	user 0.004s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3586,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:03.691838 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling MajorDeltaCompactionOp(7a192204c88340e1820ae6a2c1e7948d): perf score=1.000000
I20260812 06:19:03.910028 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: MajorDeltaCompactionOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.218s	user 0.136s	sys 0.074s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":829,"lbm_read_time_us":15795,"lbm_reads_lt_1ms":569,"lbm_write_time_us":30100,"lbm_writes_lt_1ms":543,"mutex_wait_us":2,"peak_mem_usage":63115900,"reinsert_count":0,"thread_start_us":364,"threads_started":5,"update_count":2500}
I20260812 06:19:03.910588 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d): perf score=14.095187
I20260812 06:19:03.960556 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.050s	user 0.023s	sys 0.019s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":18547,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:03.961062 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d): perf score=2.188937
I20260812 06:19:03.973515 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4200,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:03.974115 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling MajorDeltaCompactionOp(7a192204c88340e1820ae6a2c1e7948d): perf score=1.000000
I20260812 06:19:04.167179 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: MajorDeltaCompactionOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.193s	user 0.115s	sys 0.067s 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":927,"lbm_read_time_us":11031,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32263,"lbm_writes_lt_1ms":543,"mutex_wait_us":270,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":2500}
I20260812 06:19:04.167955 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d): perf score=14.095187
I20260812 06:19:04.220294 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.052s	user 0.029s	sys 0.021s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23070,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:04.220835 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d): perf score=2.188937
I20260812 06:19:04.232151 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.011s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3914,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:04.234074 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling MajorDeltaCompactionOp(7a192204c88340e1820ae6a2c1e7948d): perf score=1.000000
I20260812 06:19:04.394359 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: MajorDeltaCompactionOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.160s	user 0.114s	sys 0.043s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":274,"lbm_read_time_us":11452,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31130,"lbm_writes_lt_1ms":543,"mutex_wait_us":59,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14464,"update_count":2500}
I20260812 06:19:04.395082 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d): perf score=10.126437
I20260812 06:19:04.433511 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.038s	user 0.028s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16523,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:04.434151 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d): perf score=2.188937
I20260812 06:19:04.453780 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.019s	user 0.009s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5407,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:04.454432 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling MajorDeltaCompactionOp(7a192204c88340e1820ae6a2c1e7948d): perf score=1.000000
I20260812 06:19:04.582684 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: MajorDeltaCompactionOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.128s	user 0.096s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":556,"lbm_read_time_us":8733,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23649,"lbm_writes_lt_1ms":443,"mutex_wait_us":63,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14208,"update_count":2000}
I20260812 06:19:04.583407 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d): perf score=10.126437
I20260812 06:19:04.630911 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.047s	user 0.034s	sys 0.000s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15894,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:04.631422 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d): perf score=2.188937
I20260812 06:19:04.642957 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.011s	user 0.007s	sys 0.002s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4100,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:04.643741 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling MajorDeltaCompactionOp(7a192204c88340e1820ae6a2c1e7948d): perf score=1.000000
I20260812 06:19:04.769382 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: MajorDeltaCompactionOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.125s	user 0.080s	sys 0.045s 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":666,"lbm_read_time_us":8690,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23755,"lbm_writes_lt_1ms":443,"mutex_wait_us":51,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":21248,"update_count":2000}
I20260812 06:19:04.770117 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d): perf score=10.126437
I20260812 06:19:04.827324 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.057s	user 0.030s	sys 0.023s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":20007,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:04.828032 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d): perf score=2.188937
I20260812 06:19:04.840010 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.012s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4617,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:04.840497 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling MajorDeltaCompactionOp(7a192204c88340e1820ae6a2c1e7948d): perf score=1.000000
I20260812 06:19:05.016870 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: MajorDeltaCompactionOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.176s	user 0.116s	sys 0.060s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1018,"lbm_read_time_us":11908,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29060,"lbm_writes_lt_1ms":443,"mutex_wait_us":27,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3840,"update_count":2000}
I20260812 06:19:05.017750 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d): perf score=10.126437
I20260812 06:19:05.059044 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.041s	user 0.025s	sys 0.012s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":18133,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:05.059623 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d): perf score=2.188937
I20260812 06:19:05.086429 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.027s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6529,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:05.087035 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d): perf score=2.188937
I20260812 06:19:05.098142 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4060,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:05.098850 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling FlushMRSOp(7a192204c88340e1820ae6a2c1e7948d): perf score=1.000000
I20260812 06:19:05.131047 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: FlushMRSOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.032s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1316413,"cfile_init":1,"dirs.queue_time_us":71,"dirs.run_cpu_time_us":280,"dirs.run_wall_time_us":1372,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1858,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:19:05.131944 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling LogGCOp(7a192204c88340e1820ae6a2c1e7948d): free 133024306 bytes of WAL
I20260812 06:19:05.132205 11277 log_reader.cc:385] T 7a192204c88340e1820ae6a2c1e7948d: removed 13 log segments from log reader
I20260812 06:19:05.132251 11277 log.cc:1079] T 7a192204c88340e1820ae6a2c1e7948d P 0db5c121c6434ac197d89fd654142ba1: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/7a192204c88340e1820ae6a2c1e7948d/wal-000000003 (ops 12-16)
I20260812 06:19:05.132282 11277 log.cc:1079] T 7a192204c88340e1820ae6a2c1e7948d P 0db5c121c6434ac197d89fd654142ba1: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/7a192204c88340e1820ae6a2c1e7948d/wal-000000004 (ops 17-21)
I20260812 06:19:05.132347 11277 log.cc:1079] T 7a192204c88340e1820ae6a2c1e7948d P 0db5c121c6434ac197d89fd654142ba1: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/7a192204c88340e1820ae6a2c1e7948d/wal-000000005 (ops 22-26)
I20260812 06:19:05.132391 11277 log.cc:1079] T 7a192204c88340e1820ae6a2c1e7948d P 0db5c121c6434ac197d89fd654142ba1: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/7a192204c88340e1820ae6a2c1e7948d/wal-000000006 (ops 27-31)
I20260812 06:19:05.132436 11277 log.cc:1079] T 7a192204c88340e1820ae6a2c1e7948d P 0db5c121c6434ac197d89fd654142ba1: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/7a192204c88340e1820ae6a2c1e7948d/wal-000000007 (ops 32-36)
I20260812 06:19:05.132475 11277 log.cc:1079] T 7a192204c88340e1820ae6a2c1e7948d P 0db5c121c6434ac197d89fd654142ba1: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/7a192204c88340e1820ae6a2c1e7948d/wal-000000008 (ops 37-41)
I20260812 06:19:05.132517 11277 log.cc:1079] T 7a192204c88340e1820ae6a2c1e7948d P 0db5c121c6434ac197d89fd654142ba1: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/7a192204c88340e1820ae6a2c1e7948d/wal-000000009 (ops 42-46)
I20260812 06:19:05.132558 11277 log.cc:1079] T 7a192204c88340e1820ae6a2c1e7948d P 0db5c121c6434ac197d89fd654142ba1: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/7a192204c88340e1820ae6a2c1e7948d/wal-000000010 (ops 47-50)
I20260812 06:19:05.132598 11277 log.cc:1079] T 7a192204c88340e1820ae6a2c1e7948d P 0db5c121c6434ac197d89fd654142ba1: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/7a192204c88340e1820ae6a2c1e7948d/wal-000000011 (ops 51-55)
I20260812 06:19:05.132638 11277 log.cc:1079] T 7a192204c88340e1820ae6a2c1e7948d P 0db5c121c6434ac197d89fd654142ba1: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/7a192204c88340e1820ae6a2c1e7948d/wal-000000012 (ops 56-60)
I20260812 06:19:05.132678 11277 log.cc:1079] T 7a192204c88340e1820ae6a2c1e7948d P 0db5c121c6434ac197d89fd654142ba1: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/7a192204c88340e1820ae6a2c1e7948d/wal-000000013 (ops 61-65)
I20260812 06:19:05.132719 11277 log.cc:1079] T 7a192204c88340e1820ae6a2c1e7948d P 0db5c121c6434ac197d89fd654142ba1: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/7a192204c88340e1820ae6a2c1e7948d/wal-000000014 (ops 66-70)
I20260812 06:19:05.132761 11277 log.cc:1079] T 7a192204c88340e1820ae6a2c1e7948d P 0db5c121c6434ac197d89fd654142ba1: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/7a192204c88340e1820ae6a2c1e7948d/wal-000000015 (ops 71-75)
I20260812 06:19:05.162432 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: LogGCOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.030s	user 0.008s	sys 0.020s Metrics: {}
I20260812 06:19:05.163038 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling UndoDeltaBlockGCOp(7a192204c88340e1820ae6a2c1e7948d): 492 bytes on disk
I20260812 06:19:05.163579 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: UndoDeltaBlockGCOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":68,"lbm_reads_lt_1ms":4}
I20260812 06:19:05.164156 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d): perf score=3.181125
I20260812 06:19:05.181550 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.017s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4507,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:05.182235 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d): perf score=2.188937
I20260812 06:19:05.193202 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4057,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:05.193703 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling MajorDeltaCompactionOp(7a192204c88340e1820ae6a2c1e7948d): perf score=1.000000
I20260812 06:19:05.448937 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: MajorDeltaCompactionOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.255s	user 0.147s	sys 0.099s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979858,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":1228,"lbm_read_time_us":15169,"lbm_reads_lt_1ms":775,"lbm_write_time_us":42694,"lbm_writes_lt_1ms":743,"mutex_wait_us":414,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":5248,"thread_start_us":93,"threads_started":1,"update_count":3500}
I20260812 06:19:05.449819 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d): perf score=18.063937
I20260812 06:19:05.528565 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.078s	user 0.044s	sys 0.021s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":29502,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:05.529124 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d): perf score=2.188937
I20260812 06:19:05.539958 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4008,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:05.540441 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling MajorDeltaCompactionOp(7a192204c88340e1820ae6a2c1e7948d): perf score=1.000000
I20260812 06:19:05.736994 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: MajorDeltaCompactionOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.196s	user 0.133s	sys 0.063s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877103,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1148,"lbm_read_time_us":13167,"lbm_reads_lt_1ms":672,"lbm_write_time_us":31513,"lbm_writes_lt_1ms":643,"mutex_wait_us":391,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":3000}
I20260812 06:19:05.737887 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d): perf score=14.095187
I20260812 06:19:05.776764 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.039s	user 0.022s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17454,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:05.777259 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d): perf score=2.188937
I20260812 06:19:05.787627 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3931,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:05.788235 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling MajorDeltaCompactionOp(7a192204c88340e1820ae6a2c1e7948d): perf score=1.000000
I20260812 06:19:05.974107 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: MajorDeltaCompactionOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.186s	user 0.124s	sys 0.057s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":448,"lbm_read_time_us":12983,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31120,"lbm_writes_lt_1ms":543,"mutex_wait_us":104,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8064,"update_count":2500}
I20260812 06:19:05.974581 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d): perf score=14.095187
I20260812 06:19:06.032953 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.058s	user 0.036s	sys 0.007s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18514,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:06.033519 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d): perf score=2.188937
I20260812 06:19:06.044492 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4193,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:06.045122 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling MajorDeltaCompactionOp(7a192204c88340e1820ae6a2c1e7948d): perf score=1.000000
I20260812 06:19:06.228814 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: MajorDeltaCompactionOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.183s	user 0.119s	sys 0.059s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":301,"lbm_read_time_us":13236,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29806,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:19:06.229528 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d): perf score=11.118625
I20260812 06:19:06.263988 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.034s	user 0.025s	sys 0.009s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15010,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:06.264580 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d): perf score=2.188937
I20260812 06:19:06.289634 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.025s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4915,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:06.290280 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling MajorDeltaCompactionOp(7a192204c88340e1820ae6a2c1e7948d): perf score=1.000000
I20260812 06:19:06.445725 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: MajorDeltaCompactionOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.155s	user 0.119s	sys 0.034s 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":120,"lbm_read_time_us":9510,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23688,"lbm_writes_lt_1ms":443,"mutex_wait_us":54,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:19:06.446306 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d): perf score=11.118625
I20260812 06:19:06.482195 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.036s	user 0.017s	sys 0.016s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15440,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:06.483148 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d): perf score=2.188937
I20260812 06:19:06.498648 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5402,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:06.499235 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling MajorDeltaCompactionOp(7a192204c88340e1820ae6a2c1e7948d): perf score=1.000000
I20260812 06:19:06.625960 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: MajorDeltaCompactionOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.127s	user 0.095s	sys 0.031s 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":740,"lbm_read_time_us":7128,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24620,"lbm_writes_lt_1ms":443,"mutex_wait_us":30,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":15872,"update_count":2000}
I20260812 06:19:06.627445 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d): perf score=10.126437
I20260812 06:19:06.668256 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.040s	user 0.029s	sys 0.005s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14379,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:06.668789 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d): perf score=2.188937
I20260812 06:19:06.679359 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3958,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:06.680230 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling FlushMRSOp(7a192204c88340e1820ae6a2c1e7948d): perf score=1.000000
I20260812 06:19:06.714498 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: FlushMRSOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.034s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1234477,"cfile_init":1,"dirs.queue_time_us":82,"dirs.run_cpu_time_us":265,"dirs.run_wall_time_us":1436,"drs_written":1,"lbm_read_time_us":139,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1501,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:06.715224 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling LogGCOp(7a192204c88340e1820ae6a2c1e7948d): free 121006514 bytes of WAL
I20260812 06:19:06.715523 11277 log_reader.cc:385] T 7a192204c88340e1820ae6a2c1e7948d: removed 12 log segments from log reader
I20260812 06:19:06.715603 11277 log.cc:1079] T 7a192204c88340e1820ae6a2c1e7948d P 0db5c121c6434ac197d89fd654142ba1: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/7a192204c88340e1820ae6a2c1e7948d/wal-000000016 (ops 76-80)
I20260812 06:19:06.715655 11277 log.cc:1079] T 7a192204c88340e1820ae6a2c1e7948d P 0db5c121c6434ac197d89fd654142ba1: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/7a192204c88340e1820ae6a2c1e7948d/wal-000000017 (ops 81-85)
I20260812 06:19:06.715763 11277 log.cc:1079] T 7a192204c88340e1820ae6a2c1e7948d P 0db5c121c6434ac197d89fd654142ba1: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/7a192204c88340e1820ae6a2c1e7948d/wal-000000018 (ops 86-90)
I20260812 06:19:06.715849 11277 log.cc:1079] T 7a192204c88340e1820ae6a2c1e7948d P 0db5c121c6434ac197d89fd654142ba1: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/7a192204c88340e1820ae6a2c1e7948d/wal-000000019 (ops 91-94)
I20260812 06:19:06.715902 11277 log.cc:1079] T 7a192204c88340e1820ae6a2c1e7948d P 0db5c121c6434ac197d89fd654142ba1: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/7a192204c88340e1820ae6a2c1e7948d/wal-000000020 (ops 95-99)
I20260812 06:19:06.715947 11277 log.cc:1079] T 7a192204c88340e1820ae6a2c1e7948d P 0db5c121c6434ac197d89fd654142ba1: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/7a192204c88340e1820ae6a2c1e7948d/wal-000000021 (ops 100-104)
I20260812 06:19:06.715998 11277 log.cc:1079] T 7a192204c88340e1820ae6a2c1e7948d P 0db5c121c6434ac197d89fd654142ba1: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/7a192204c88340e1820ae6a2c1e7948d/wal-000000022 (ops 105-109)
I20260812 06:19:06.716034 11277 log.cc:1079] T 7a192204c88340e1820ae6a2c1e7948d P 0db5c121c6434ac197d89fd654142ba1: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/7a192204c88340e1820ae6a2c1e7948d/wal-000000023 (ops 110-114)
I20260812 06:19:06.716073 11277 log.cc:1079] T 7a192204c88340e1820ae6a2c1e7948d P 0db5c121c6434ac197d89fd654142ba1: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/7a192204c88340e1820ae6a2c1e7948d/wal-000000024 (ops 115-119)
I20260812 06:19:06.716109 11277 log.cc:1079] T 7a192204c88340e1820ae6a2c1e7948d P 0db5c121c6434ac197d89fd654142ba1: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/7a192204c88340e1820ae6a2c1e7948d/wal-000000025 (ops 120-124)
I20260812 06:19:06.716152 11277 log.cc:1079] T 7a192204c88340e1820ae6a2c1e7948d P 0db5c121c6434ac197d89fd654142ba1: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/7a192204c88340e1820ae6a2c1e7948d/wal-000000026 (ops 125-129)
I20260812 06:19:06.716192 11277 log.cc:1079] T 7a192204c88340e1820ae6a2c1e7948d P 0db5c121c6434ac197d89fd654142ba1: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/7a192204c88340e1820ae6a2c1e7948d/wal-000000027 (ops 130-134)
I20260812 06:19:06.741389 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: LogGCOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.026s	user 0.001s	sys 0.023s Metrics: {}
I20260812 06:19:06.741834 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d): perf score=3.181125
I20260812 06:19:06.761770 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.020s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4512899,"delete_count":0,"lbm_write_time_us":7108,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:06.762233 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling UndoDeltaBlockGCOp(7a192204c88340e1820ae6a2c1e7948d): 472 bytes on disk
I20260812 06:19:06.762635 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: UndoDeltaBlockGCOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4}
I20260812 06:19:06.763130 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d): perf score=2.188937
I20260812 06:19:06.772887 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3570,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:06.773360 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling MajorDeltaCompactionOp(7a192204c88340e1820ae6a2c1e7948d): perf score=1.000000
I20260812 06:19:06.948838 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: MajorDeltaCompactionOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.175s	user 0.135s	sys 0.039s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877325,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":491,"lbm_read_time_us":13042,"lbm_reads_lt_1ms":674,"lbm_write_time_us":34759,"lbm_writes_lt_1ms":643,"mutex_wait_us":24,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":14720,"thread_start_us":89,"threads_started":1,"update_count":3000}
I20260812 06:19:06.951908 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d): perf score=14.095187
I20260812 06:19:06.994014 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.041s	user 0.019s	sys 0.020s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18756,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:06.994594 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d): perf score=2.188937
I20260812 06:19:07.007170 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4260,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:07.007774 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling MajorDeltaCompactionOp(7a192204c88340e1820ae6a2c1e7948d): perf score=1.000000
I20260812 06:19:07.173053 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: MajorDeltaCompactionOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.164s	user 0.120s	sys 0.040s 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":260,"lbm_read_time_us":11500,"lbm_reads_lt_1ms":564,"lbm_write_time_us":31273,"lbm_writes_lt_1ms":543,"mutex_wait_us":68,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4736,"update_count":2500}
I20260812 06:19:07.173957 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d): perf score=12.110812
I20260812 06:19:07.214955 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.041s	user 0.021s	sys 0.016s Metrics: {"bytes_written":13538208,"delete_count":0,"lbm_write_time_us":17746,"lbm_writes_lt_1ms":333,"reinsert_count":0,"update_count":1650}
I20260812 06:19:07.215515 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d): perf score=1.196750
I20260812 06:19:07.232543 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.017s	user 0.006s	sys 0.004s Metrics: {"bytes_written":2871905,"delete_count":0,"lbm_write_time_us":4055,"lbm_writes_lt_1ms":73,"reinsert_count":0,"update_count":350}
I20260812 06:19:07.233110 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling MajorDeltaCompactionOp(7a192204c88340e1820ae6a2c1e7948d): perf score=1.000000
I20260812 06:19:07.396369 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: MajorDeltaCompactionOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.163s	user 0.101s	sys 0.049s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672241,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":449,"lbm_read_time_us":9296,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25971,"lbm_writes_lt_1ms":443,"mutex_wait_us":94,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:07.396960 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d): perf score=14.095187
I20260812 06:19:07.448741 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.052s	user 0.035s	sys 0.008s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":19442,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:07.449281 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d): perf score=2.188937
I20260812 06:19:07.470096 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.021s	user 0.004s	sys 0.014s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4271,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:07.470794 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling MajorDeltaCompactionOp(7a192204c88340e1820ae6a2c1e7948d): perf score=1.000000
I20260812 06:19:07.657337 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: MajorDeltaCompactionOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.186s	user 0.128s	sys 0.054s 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":972,"lbm_read_time_us":14958,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29645,"lbm_writes_lt_1ms":543,"mutex_wait_us":255,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13184,"update_count":2500}
I20260812 06:19:07.658079 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d): perf score=14.095187
I20260812 06:19:07.707489 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.049s	user 0.027s	sys 0.013s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":18801,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:07.708175 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d): perf score=2.188937
I20260812 06:19:07.720433 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.012s	user 0.004s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4304,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:07.721076 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling MajorDeltaCompactionOp(7a192204c88340e1820ae6a2c1e7948d): perf score=1.000000
I20260812 06:19:07.906584 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: MajorDeltaCompactionOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.185s	user 0.102s	sys 0.069s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":436,"lbm_read_time_us":10135,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28620,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4480,"update_count":2500}
I20260812 06:19:07.907096 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d): perf score=14.095187
I20260812 06:19:07.964339 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.057s	user 0.043s	sys 0.008s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":22708,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:07.964855 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d): perf score=2.188937
I20260812 06:19:07.976250 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.011s	user 0.010s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3891,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:07.976783 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling MajorDeltaCompactionOp(7a192204c88340e1820ae6a2c1e7948d): perf score=1.000000
I20260812 06:19:08.121057 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: MajorDeltaCompactionOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.144s	user 0.126s	sys 0.016s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":229,"lbm_read_time_us":11010,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28754,"lbm_writes_lt_1ms":543,"mutex_wait_us":3,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6272,"update_count":2500}
I20260812 06:19:08.121845 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d): perf score=10.126437
I20260812 06:19:08.155294 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.033s	user 0.013s	sys 0.016s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":14532,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:08.156167 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d): perf score=2.188937
I20260812 06:19:08.167613 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4283,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:08.168179 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling FlushMRSOp(7a192204c88340e1820ae6a2c1e7948d): perf score=1.000000
I20260812 06:19:08.203536 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: FlushMRSOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.034s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1234477,"cfile_init":1,"dirs.queue_time_us":62,"dirs.run_cpu_time_us":227,"dirs.run_wall_time_us":1307,"drs_written":1,"lbm_read_time_us":116,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1665,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:08.204282 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling LogGCOp(7a192204c88340e1820ae6a2c1e7948d): free 120553644 bytes of WAL
I20260812 06:19:08.204519 11277 log_reader.cc:385] T 7a192204c88340e1820ae6a2c1e7948d: removed 12 log segments from log reader
I20260812 06:19:08.204564 11277 log.cc:1079] T 7a192204c88340e1820ae6a2c1e7948d P 0db5c121c6434ac197d89fd654142ba1: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/7a192204c88340e1820ae6a2c1e7948d/wal-000000028 (ops 135-138)
I20260812 06:19:08.204593 11277 log.cc:1079] T 7a192204c88340e1820ae6a2c1e7948d P 0db5c121c6434ac197d89fd654142ba1: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/7a192204c88340e1820ae6a2c1e7948d/wal-000000029 (ops 139-143)
I20260812 06:19:08.204653 11277 log.cc:1079] T 7a192204c88340e1820ae6a2c1e7948d P 0db5c121c6434ac197d89fd654142ba1: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/7a192204c88340e1820ae6a2c1e7948d/wal-000000030 (ops 144-148)
I20260812 06:19:08.204695 11277 log.cc:1079] T 7a192204c88340e1820ae6a2c1e7948d P 0db5c121c6434ac197d89fd654142ba1: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/7a192204c88340e1820ae6a2c1e7948d/wal-000000031 (ops 149-152)
I20260812 06:19:08.204737 11277 log.cc:1079] T 7a192204c88340e1820ae6a2c1e7948d P 0db5c121c6434ac197d89fd654142ba1: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/7a192204c88340e1820ae6a2c1e7948d/wal-000000032 (ops 153-157)
I20260812 06:19:08.204774 11277 log.cc:1079] T 7a192204c88340e1820ae6a2c1e7948d P 0db5c121c6434ac197d89fd654142ba1: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/7a192204c88340e1820ae6a2c1e7948d/wal-000000033 (ops 158-162)
I20260812 06:19:08.204813 11277 log.cc:1079] T 7a192204c88340e1820ae6a2c1e7948d P 0db5c121c6434ac197d89fd654142ba1: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/7a192204c88340e1820ae6a2c1e7948d/wal-000000034 (ops 163-167)
I20260812 06:19:08.204852 11277 log.cc:1079] T 7a192204c88340e1820ae6a2c1e7948d P 0db5c121c6434ac197d89fd654142ba1: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/7a192204c88340e1820ae6a2c1e7948d/wal-000000035 (ops 168-172)
I20260812 06:19:08.204890 11277 log.cc:1079] T 7a192204c88340e1820ae6a2c1e7948d P 0db5c121c6434ac197d89fd654142ba1: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/7a192204c88340e1820ae6a2c1e7948d/wal-000000036 (ops 173-177)
I20260812 06:19:08.204931 11277 log.cc:1079] T 7a192204c88340e1820ae6a2c1e7948d P 0db5c121c6434ac197d89fd654142ba1: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/7a192204c88340e1820ae6a2c1e7948d/wal-000000037 (ops 178-182)
I20260812 06:19:08.204969 11277 log.cc:1079] T 7a192204c88340e1820ae6a2c1e7948d P 0db5c121c6434ac197d89fd654142ba1: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/7a192204c88340e1820ae6a2c1e7948d/wal-000000038 (ops 183-187)
I20260812 06:19:08.205008 11277 log.cc:1079] T 7a192204c88340e1820ae6a2c1e7948d P 0db5c121c6434ac197d89fd654142ba1: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/7a192204c88340e1820ae6a2c1e7948d/wal-000000039 (ops 188-192)
I20260812 06:19:08.230921 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: LogGCOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.026s	user 0.005s	sys 0.019s Metrics: {}
I20260812 06:19:08.231491 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d): perf score=5.165500
I20260812 06:19:08.247180 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.016s	user 0.013s	sys 0.000s Metrics: {"bytes_written":6317966,"delete_count":0,"lbm_write_time_us":6443,"lbm_writes_lt_1ms":157,"reinsert_count":0,"update_count":770}
I20260812 06:19:08.247886 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling LogGCOp(7a192204c88340e1820ae6a2c1e7948d): free 11564893 bytes of WAL
I20260812 06:19:08.248207 11277 log_reader.cc:385] T 7a192204c88340e1820ae6a2c1e7948d: removed 1 log segments from log reader
I20260812 06:19:08.248286 11277 log.cc:1079] T 7a192204c88340e1820ae6a2c1e7948d P 0db5c121c6434ac197d89fd654142ba1: Deleting log segment in path: /tmp/dist-test-taskApLH5Q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537863371-10991-0/minicluster-data/ts-0-root/wals/7a192204c88340e1820ae6a2c1e7948d/wal-000000040 (ops 193-196)
I20260812 06:19:08.251035 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: LogGCOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:19:08.251513 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d): perf score=1.000000
I20260812 06:19:08.259119 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.007s	user 0.005s	sys 0.000s Metrics: {"bytes_written":1887302,"delete_count":0,"lbm_write_time_us":2170,"lbm_writes_lt_1ms":49,"reinsert_count":0,"update_count":230}
I20260812 06:19:08.259763 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling MajorDeltaCompactionOp(7a192204c88340e1820ae6a2c1e7948d): perf score=1.000000
I20260812 06:19:08.345795 10991 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.013s	user 1.826s	sys 0.162s
I20260812 06:19:08.424816 10991 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.079s	user 0.002s	sys 0.000s
I20260812 06:19:08.425310 10991 tablet_server.cc:179] TabletServer@127.10.187.193:0 shutting down...
I20260812 06:19:08.427933 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: MajorDeltaCompactionOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.168s	user 0.116s	sys 0.051s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877286,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":409,"lbm_read_time_us":13217,"lbm_reads_lt_1ms":670,"lbm_write_time_us":32776,"lbm_writes_lt_1ms":643,"mutex_wait_us":36,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":14336,"thread_start_us":68,"threads_started":1,"update_count":3000}
I20260812 06:19:08.428587 11337 maintenance_manager.cc:419] P 0db5c121c6434ac197d89fd654142ba1: Scheduling FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d): perf score=6.157687
I20260812 06:19:08.450609 11277 maintenance_manager.cc:643] P 0db5c121c6434ac197d89fd654142ba1: FlushDeltaMemStoresOp(7a192204c88340e1820ae6a2c1e7948d) complete. Timing: real 0.022s	user 0.013s	sys 0.005s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":9096,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:19:08.451289 10991 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:08.451550 10991 tablet_replica.cc:333] T 7a192204c88340e1820ae6a2c1e7948d P 0db5c121c6434ac197d89fd654142ba1: stopping tablet replica
I20260812 06:19:08.451757 10991 raft_consensus.cc:2243] T 7a192204c88340e1820ae6a2c1e7948d P 0db5c121c6434ac197d89fd654142ba1 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:08.451958 10991 raft_consensus.cc:2272] T 7a192204c88340e1820ae6a2c1e7948d P 0db5c121c6434ac197d89fd654142ba1 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:08.465562 10991 tablet_server.cc:196] TabletServer@127.10.187.193:0 shutdown complete.
I20260812 06:19:08.477519 10991 master.cc:562] Master@127.10.187.254:40309 shutting down...
I20260812 06:19:08.481016 10991 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 2e1e329b65564e4bbc4a2b9fec456c0b [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:08.481252 10991 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 2e1e329b65564e4bbc4a2b9fec456c0b [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:08.481352 10991 tablet_replica.cc:333] T 00000000000000000000000000000000 P 2e1e329b65564e4bbc4a2b9fec456c0b: stopping tablet replica
I20260812 06:19:08.494053 10991 master.cc:584] Master@127.10.187.254:40309 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5452 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10702 ms total)

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