[==========] 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:29.358534 24067 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.23.128.254:33315
I20260812 06:18:29.359419 24067 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:29.359951 24067 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:29.365976 24077 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:29.366060 24074 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:29.366044 24067 server_base.cc:1061] running on GCE node
W20260812 06:18:29.366218 24075 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:29.366698 24067 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:29.366791 24067 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:29.366829 24067 hybrid_clock.cc:648] HybridClock initialized: now 1786515509366827 us; error 0 us; skew 500 ppm
I20260812 06:18:29.368587 24067 webserver.cc:533] Webserver started at http://127.23.128.254:39809/ using document root <none> and password file <none>
I20260812 06:18:29.369102 24067 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:29.369168 24067 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:29.369390 24067 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:29.370971 24067 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515509348364-24067-0/minicluster-data/master-0-root/instance:
uuid: "98af9c9f38184667a97b077a0c3b7f82"
format_stamp: "Formatted at 2026-08-12 06:18:29 on dist-test-slave-1l3l"
I20260812 06:18:29.374259 24067 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.005s	sys 0.000s
I20260812 06:18:29.376224 24087 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:29.377142 24067 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:29.377244 24067 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515509348364-24067-0/minicluster-data/master-0-root
uuid: "98af9c9f38184667a97b077a0c3b7f82"
format_stamp: "Formatted at 2026-08-12 06:18:29 on dist-test-slave-1l3l"
I20260812 06:18:29.377337 24067 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515509348364-24067-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515509348364-24067-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515509348364-24067-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:29.395766 24067 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:29.396348 24067 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:29.396502 24067 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:29.403537 24190 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.23.128.254:33315 every 8 connection(s)
I20260812 06:18:29.403537 24067 rpc_server.cc:307] RPC server started. Bound to: 127.23.128.254:33315
I20260812 06:18:29.405700 24191 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:29.410912 24191 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 98af9c9f38184667a97b077a0c3b7f82: Bootstrap starting.
I20260812 06:18:29.413130 24191 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 98af9c9f38184667a97b077a0c3b7f82: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:29.413931 24191 log.cc:826] T 00000000000000000000000000000000 P 98af9c9f38184667a97b077a0c3b7f82: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:29.415462 24191 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 98af9c9f38184667a97b077a0c3b7f82: No bootstrap required, opened a new log
I20260812 06:18:29.418092 24191 raft_consensus.cc:359] T 00000000000000000000000000000000 P 98af9c9f38184667a97b077a0c3b7f82 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "98af9c9f38184667a97b077a0c3b7f82" member_type: VOTER }
I20260812 06:18:29.418251 24191 raft_consensus.cc:385] T 00000000000000000000000000000000 P 98af9c9f38184667a97b077a0c3b7f82 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:29.418300 24191 raft_consensus.cc:740] T 00000000000000000000000000000000 P 98af9c9f38184667a97b077a0c3b7f82 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 98af9c9f38184667a97b077a0c3b7f82, State: Initialized, Role: FOLLOWER
I20260812 06:18:29.418846 24191 consensus_queue.cc:260] T 00000000000000000000000000000000 P 98af9c9f38184667a97b077a0c3b7f82 [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: "98af9c9f38184667a97b077a0c3b7f82" member_type: VOTER }
I20260812 06:18:29.418983 24191 raft_consensus.cc:399] T 00000000000000000000000000000000 P 98af9c9f38184667a97b077a0c3b7f82 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:29.419028 24191 raft_consensus.cc:493] T 00000000000000000000000000000000 P 98af9c9f38184667a97b077a0c3b7f82 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:29.419114 24191 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 98af9c9f38184667a97b077a0c3b7f82 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:29.419817 24191 raft_consensus.cc:515] T 00000000000000000000000000000000 P 98af9c9f38184667a97b077a0c3b7f82 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "98af9c9f38184667a97b077a0c3b7f82" member_type: VOTER }
I20260812 06:18:29.420174 24191 leader_election.cc:304] T 00000000000000000000000000000000 P 98af9c9f38184667a97b077a0c3b7f82 [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: 98af9c9f38184667a97b077a0c3b7f82; no voters: 
I20260812 06:18:29.420424 24191 leader_election.cc:290] T 00000000000000000000000000000000 P 98af9c9f38184667a97b077a0c3b7f82 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:29.420536 24199 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 98af9c9f38184667a97b077a0c3b7f82 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:29.420758 24199 raft_consensus.cc:697] T 00000000000000000000000000000000 P 98af9c9f38184667a97b077a0c3b7f82 [term 1 LEADER]: Becoming Leader. State: Replica: 98af9c9f38184667a97b077a0c3b7f82, State: Running, Role: LEADER
I20260812 06:18:29.421141 24199 consensus_queue.cc:237] T 00000000000000000000000000000000 P 98af9c9f38184667a97b077a0c3b7f82 [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: "98af9c9f38184667a97b077a0c3b7f82" member_type: VOTER }
I20260812 06:18:29.421283 24191 sys_catalog.cc:565] T 00000000000000000000000000000000 P 98af9c9f38184667a97b077a0c3b7f82 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:29.422930 24200 sys_catalog.cc:455] T 00000000000000000000000000000000 P 98af9c9f38184667a97b077a0c3b7f82 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "98af9c9f38184667a97b077a0c3b7f82" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "98af9c9f38184667a97b077a0c3b7f82" member_type: VOTER } }
I20260812 06:18:29.422974 24201 sys_catalog.cc:455] T 00000000000000000000000000000000 P 98af9c9f38184667a97b077a0c3b7f82 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 98af9c9f38184667a97b077a0c3b7f82. Latest consensus state: current_term: 1 leader_uuid: "98af9c9f38184667a97b077a0c3b7f82" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "98af9c9f38184667a97b077a0c3b7f82" member_type: VOTER } }
I20260812 06:18:29.423059 24200 sys_catalog.cc:458] T 00000000000000000000000000000000 P 98af9c9f38184667a97b077a0c3b7f82 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:29.423063 24201 sys_catalog.cc:458] T 00000000000000000000000000000000 P 98af9c9f38184667a97b077a0c3b7f82 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:29.423381 24223 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:29.423509 24067 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:29.425545 24223 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:29.429694 24223 catalog_manager.cc:1383] Generated new cluster ID: c34d876ea55846a7bc86375c28e400ad
I20260812 06:18:29.429754 24223 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:29.443686 24223 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:29.444792 24223 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:29.455849 24223 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 98af9c9f38184667a97b077a0c3b7f82: Generated new TSK 0
I20260812 06:18:29.456542 24223 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:29.488770 24067 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:29.491662 24234 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:29.491721 24232 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:29.491910 24067 server_base.cc:1061] running on GCE node
W20260812 06:18:29.491772 24238 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:29.492244 24067 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:29.492290 24067 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:29.492324 24067 hybrid_clock.cc:648] HybridClock initialized: now 1786515509492324 us; error 0 us; skew 500 ppm
I20260812 06:18:29.493211 24067 webserver.cc:533] Webserver started at http://127.23.128.193:34667/ using document root <none> and password file <none>
I20260812 06:18:29.493376 24067 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:29.493427 24067 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:29.493502 24067 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:29.493896 24067 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515509348364-24067-0/minicluster-data/ts-0-root/instance:
uuid: "de1cb23db8cc4eae908d21d0d0236e49"
format_stamp: "Formatted at 2026-08-12 06:18:29 on dist-test-slave-1l3l"
I20260812 06:18:29.495329 24067 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:29.496259 24247 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:29.496479 24067 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.000s
I20260812 06:18:29.496549 24067 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515509348364-24067-0/minicluster-data/ts-0-root
uuid: "de1cb23db8cc4eae908d21d0d0236e49"
format_stamp: "Formatted at 2026-08-12 06:18:29 on dist-test-slave-1l3l"
I20260812 06:18:29.496618 24067 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515509348364-24067-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515509348364-24067-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515509348364-24067-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:29.511270 24067 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:29.511664 24067 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:29.512130 24067 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:29.513136 24067 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:29.513245 24067 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:29.513324 24067 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:29.513348 24067 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:29.519575 24067 rpc_server.cc:307] RPC server started. Bound to: 127.23.128.193:40109
I20260812 06:18:29.519757 24374 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.23.128.193:40109 every 8 connection(s)
I20260812 06:18:29.529284 24375 heartbeater.cc:344] Connected to a master server at 127.23.128.254:33315
I20260812 06:18:29.529520 24375 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:29.529983 24375 heartbeater.cc:507] Master 127.23.128.254:33315 requested a full tablet report, sending...
I20260812 06:18:29.531400 24126 ts_manager.cc:194] Registered new tserver with Master: de1cb23db8cc4eae908d21d0d0236e49 (127.23.128.193:40109)
I20260812 06:18:29.531487 24067 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011251518s
I20260812 06:18:29.532889 24126 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:42726
I20260812 06:18:29.540117 24126 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:42742:
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:29.552635 24308 tablet_service.cc:1511] Processing CreateTablet for tablet 77cfd638a34e4ff9bee3b1e5e77ae600 (DEFAULT_TABLE table=heavy-update-compaction-test [id=f14bf7c2c0ec4b6886c770c7067b8916]), partition=
I20260812 06:18:29.553028 24308 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 77cfd638a34e4ff9bee3b1e5e77ae600. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:29.555330 24393 tablet_bootstrap.cc:492] T 77cfd638a34e4ff9bee3b1e5e77ae600 P de1cb23db8cc4eae908d21d0d0236e49: Bootstrap starting.
I20260812 06:18:29.556283 24393 tablet_bootstrap.cc:654] T 77cfd638a34e4ff9bee3b1e5e77ae600 P de1cb23db8cc4eae908d21d0d0236e49: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:29.557754 24393 tablet_bootstrap.cc:492] T 77cfd638a34e4ff9bee3b1e5e77ae600 P de1cb23db8cc4eae908d21d0d0236e49: No bootstrap required, opened a new log
I20260812 06:18:29.557835 24393 ts_tablet_manager.cc:1403] T 77cfd638a34e4ff9bee3b1e5e77ae600 P de1cb23db8cc4eae908d21d0d0236e49: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:18:29.558272 24393 raft_consensus.cc:359] T 77cfd638a34e4ff9bee3b1e5e77ae600 P de1cb23db8cc4eae908d21d0d0236e49 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "de1cb23db8cc4eae908d21d0d0236e49" member_type: VOTER last_known_addr { host: "127.23.128.193" port: 40109 } }
I20260812 06:18:29.558367 24393 raft_consensus.cc:385] T 77cfd638a34e4ff9bee3b1e5e77ae600 P de1cb23db8cc4eae908d21d0d0236e49 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:29.558389 24393 raft_consensus.cc:740] T 77cfd638a34e4ff9bee3b1e5e77ae600 P de1cb23db8cc4eae908d21d0d0236e49 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: de1cb23db8cc4eae908d21d0d0236e49, State: Initialized, Role: FOLLOWER
I20260812 06:18:29.558511 24393 consensus_queue.cc:260] T 77cfd638a34e4ff9bee3b1e5e77ae600 P de1cb23db8cc4eae908d21d0d0236e49 [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: "de1cb23db8cc4eae908d21d0d0236e49" member_type: VOTER last_known_addr { host: "127.23.128.193" port: 40109 } }
I20260812 06:18:29.558583 24393 raft_consensus.cc:399] T 77cfd638a34e4ff9bee3b1e5e77ae600 P de1cb23db8cc4eae908d21d0d0236e49 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:29.558609 24393 raft_consensus.cc:493] T 77cfd638a34e4ff9bee3b1e5e77ae600 P de1cb23db8cc4eae908d21d0d0236e49 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:29.558655 24393 raft_consensus.cc:3060] T 77cfd638a34e4ff9bee3b1e5e77ae600 P de1cb23db8cc4eae908d21d0d0236e49 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:29.559378 24393 raft_consensus.cc:515] T 77cfd638a34e4ff9bee3b1e5e77ae600 P de1cb23db8cc4eae908d21d0d0236e49 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "de1cb23db8cc4eae908d21d0d0236e49" member_type: VOTER last_known_addr { host: "127.23.128.193" port: 40109 } }
I20260812 06:18:29.559505 24393 leader_election.cc:304] T 77cfd638a34e4ff9bee3b1e5e77ae600 P de1cb23db8cc4eae908d21d0d0236e49 [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: de1cb23db8cc4eae908d21d0d0236e49; no voters: 
I20260812 06:18:29.559690 24393 leader_election.cc:290] T 77cfd638a34e4ff9bee3b1e5e77ae600 P de1cb23db8cc4eae908d21d0d0236e49 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:29.559819 24396 raft_consensus.cc:2804] T 77cfd638a34e4ff9bee3b1e5e77ae600 P de1cb23db8cc4eae908d21d0d0236e49 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:29.559989 24396 raft_consensus.cc:697] T 77cfd638a34e4ff9bee3b1e5e77ae600 P de1cb23db8cc4eae908d21d0d0236e49 [term 1 LEADER]: Becoming Leader. State: Replica: de1cb23db8cc4eae908d21d0d0236e49, State: Running, Role: LEADER
I20260812 06:18:29.560039 24393 ts_tablet_manager.cc:1434] T 77cfd638a34e4ff9bee3b1e5e77ae600 P de1cb23db8cc4eae908d21d0d0236e49: Time spent starting tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:29.560324 24375 heartbeater.cc:499] Master 127.23.128.254:33315 was elected leader, sending a full tablet report...
I20260812 06:18:29.560364 24396 consensus_queue.cc:237] T 77cfd638a34e4ff9bee3b1e5e77ae600 P de1cb23db8cc4eae908d21d0d0236e49 [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: "de1cb23db8cc4eae908d21d0d0236e49" member_type: VOTER last_known_addr { host: "127.23.128.193" port: 40109 } }
I20260812 06:18:29.562779 24126 catalog_manager.cc:5719] T 77cfd638a34e4ff9bee3b1e5e77ae600 P de1cb23db8cc4eae908d21d0d0236e49 reported cstate change: term changed from 0 to 1, leader changed from <none> to de1cb23db8cc4eae908d21d0d0236e49 (127.23.128.193). New cstate: current_term: 1 leader_uuid: "de1cb23db8cc4eae908d21d0d0236e49" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "de1cb23db8cc4eae908d21d0d0236e49" member_type: VOTER last_known_addr { host: "127.23.128.193" port: 40109 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:29.626134 24067 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.057s	user 0.004s	sys 0.025s
I20260812 06:18:29.770717 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling FlushMRSOp(77cfd638a34e4ff9bee3b1e5e77ae600): perf score=19.054940
I20260812 06:18:29.919313 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: FlushMRSOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.148s	user 0.097s	sys 0.044s Metrics: {"bytes_written":11897249,"cfile_init":1,"compiler_manager_pool.queue_time_us":228,"delete_count":0,"dirs.queue_time_us":64,"dirs.run_cpu_time_us":217,"dirs.run_wall_time_us":755,"drs_written":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4,"lbm_write_time_us":36374,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"thread_start_us":134,"threads_started":1,"update_count":1450}
I20260812 06:18:29.920463 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling LogGCOp(77cfd638a34e4ff9bee3b1e5e77ae600): free 20743880 bytes of WAL
I20260812 06:18:29.920756 24258 log_reader.cc:385] T 77cfd638a34e4ff9bee3b1e5e77ae600: removed 2 log segments from log reader
I20260812 06:18:29.920822 24258 log.cc:1079] T 77cfd638a34e4ff9bee3b1e5e77ae600 P de1cb23db8cc4eae908d21d0d0236e49: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/77cfd638a34e4ff9bee3b1e5e77ae600/wal-000000001 (ops 1-6)
I20260812 06:18:29.920871 24258 log.cc:1079] T 77cfd638a34e4ff9bee3b1e5e77ae600 P de1cb23db8cc4eae908d21d0d0236e49: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/77cfd638a34e4ff9bee3b1e5e77ae600/wal-000000002 (ops 7-11)
I20260812 06:18:29.926173 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: LogGCOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.006s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:18:29.926674 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600): perf score=2.188937
I20260812 06:18:29.945807 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.019s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6542,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:29.946266 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling UndoDeltaBlockGCOp(77cfd638a34e4ff9bee3b1e5e77ae600): 16821646 bytes on disk
I20260812 06:18:29.946847 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: UndoDeltaBlockGCOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4}
I20260812 06:18:29.947295 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling MajorDeltaCompactionOp(77cfd638a34e4ff9bee3b1e5e77ae600): perf score=1.000000
I20260812 06:18:30.075461 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: MajorDeltaCompactionOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.128s	user 0.076s	sys 0.048s Metrics: {"cfile_cache_miss":422,"cfile_cache_miss_bytes":20303031,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":530,"lbm_read_time_us":8166,"lbm_reads_lt_1ms":450,"lbm_write_time_us":20486,"lbm_writes_lt_1ms":433,"peak_mem_usage":49238594,"reinsert_count":0,"thread_start_us":329,"threads_started":5,"update_count":1950}
I20260812 06:18:30.076049 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600): perf score=10.126437
I20260812 06:18:30.112491 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.036s	user 0.019s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15997,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:30.113035 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600): perf score=2.188937
I20260812 06:18:30.129755 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.017s	user 0.014s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6547,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:30.130209 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling MajorDeltaCompactionOp(77cfd638a34e4ff9bee3b1e5e77ae600): perf score=1.000000
I20260812 06:18:30.242630 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: MajorDeltaCompactionOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.112s	user 0.091s	sys 0.021s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1106,"lbm_read_time_us":7098,"lbm_reads_lt_1ms":468,"lbm_write_time_us":23717,"lbm_writes_lt_1ms":443,"mutex_wait_us":322,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8192,"update_count":2000}
I20260812 06:18:30.245309 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600): perf score=10.126437
I20260812 06:18:30.287361 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.042s	user 0.028s	sys 0.008s Metrics: {"bytes_written":12307540,"delete_count":0,"lbm_write_time_us":20065,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:18:30.288069 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600): perf score=2.188937
I20260812 06:18:30.303196 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5465,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:30.303678 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling MajorDeltaCompactionOp(77cfd638a34e4ff9bee3b1e5e77ae600): perf score=1.000000
I20260812 06:18:30.427752 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: MajorDeltaCompactionOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.124s	user 0.097s	sys 0.022s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713321,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":3296,"lbm_read_time_us":8832,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23335,"lbm_writes_lt_1ms":443,"mutex_wait_us":2663,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7936,"update_count":2000}
I20260812 06:18:30.428244 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600): perf score=11.118625
I20260812 06:18:30.461376 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.033s	user 0.020s	sys 0.011s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":11359,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:30.462035 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600): perf score=2.188937
I20260812 06:18:30.475683 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.013s	user 0.004s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5068,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:30.476241 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling MajorDeltaCompactionOp(77cfd638a34e4ff9bee3b1e5e77ae600): perf score=1.000000
I20260812 06:18:30.614936 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: MajorDeltaCompactionOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.139s	user 0.084s	sys 0.054s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713262,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":774,"lbm_read_time_us":9423,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23076,"lbm_writes_lt_1ms":443,"mutex_wait_us":44,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:18:30.615477 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600): perf score=10.126437
I20260812 06:18:30.642930 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.027s	user 0.022s	sys 0.003s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":11731,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:30.643535 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600): perf score=2.188937
I20260812 06:18:30.661677 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.018s	user 0.003s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5348,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:30.662128 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling MajorDeltaCompactionOp(77cfd638a34e4ff9bee3b1e5e77ae600): perf score=1.000000
I20260812 06:18:30.785245 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: MajorDeltaCompactionOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.123s	user 0.098s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713273,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":513,"lbm_read_time_us":8078,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24567,"lbm_writes_lt_1ms":443,"mutex_wait_us":1,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11136,"update_count":2000}
I20260812 06:18:30.787379 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600): perf score=11.118625
I20260812 06:18:30.822742 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.035s	user 0.022s	sys 0.010s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15303,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:30.823203 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600): perf score=2.188937
I20260812 06:18:30.833595 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3624,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:30.834017 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling MajorDeltaCompactionOp(77cfd638a34e4ff9bee3b1e5e77ae600): perf score=1.000000
I20260812 06:18:30.948802 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: MajorDeltaCompactionOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.115s	user 0.094s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713263,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":187,"lbm_read_time_us":8305,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23386,"lbm_writes_lt_1ms":443,"mutex_wait_us":57,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14208,"update_count":2000}
I20260812 06:18:30.950966 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600): perf score=10.126437
I20260812 06:18:30.981505 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.030s	user 0.021s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12693,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:30.982002 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600): perf score=2.188937
I20260812 06:18:30.996999 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.015s	user 0.008s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5279,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:30.997531 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling MajorDeltaCompactionOp(77cfd638a34e4ff9bee3b1e5e77ae600): perf score=1.000000
I20260812 06:18:31.118093 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: MajorDeltaCompactionOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.120s	user 0.086s	sys 0.034s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":621,"lbm_read_time_us":8185,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24063,"lbm_writes_lt_1ms":443,"mutex_wait_us":240,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:18:31.118597 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600): perf score=10.126437
I20260812 06:18:31.160938 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.042s	user 0.029s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14035,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:31.161561 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600): perf score=2.188937
I20260812 06:18:31.171921 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3893,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:31.172401 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling FlushMRSOp(77cfd638a34e4ff9bee3b1e5e77ae600): perf score=1.000000
I20260812 06:18:31.211324 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: FlushMRSOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.039s	user 0.027s	sys 0.000s Metrics: {"bytes_written":1275444,"cfile_init":1,"dirs.queue_time_us":32,"dirs.run_cpu_time_us":190,"dirs.run_wall_time_us":1142,"drs_written":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1443,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:31.212348 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling LogGCOp(77cfd638a34e4ff9bee3b1e5e77ae600): free 133024309 bytes of WAL
I20260812 06:18:31.212600 24258 log_reader.cc:385] T 77cfd638a34e4ff9bee3b1e5e77ae600: removed 13 log segments from log reader
I20260812 06:18:31.212651 24258 log.cc:1079] T 77cfd638a34e4ff9bee3b1e5e77ae600 P de1cb23db8cc4eae908d21d0d0236e49: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/77cfd638a34e4ff9bee3b1e5e77ae600/wal-000000003 (ops 12-16)
I20260812 06:18:31.212690 24258 log.cc:1079] T 77cfd638a34e4ff9bee3b1e5e77ae600 P de1cb23db8cc4eae908d21d0d0236e49: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/77cfd638a34e4ff9bee3b1e5e77ae600/wal-000000004 (ops 17-21)
I20260812 06:18:31.212724 24258 log.cc:1079] T 77cfd638a34e4ff9bee3b1e5e77ae600 P de1cb23db8cc4eae908d21d0d0236e49: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/77cfd638a34e4ff9bee3b1e5e77ae600/wal-000000005 (ops 22-26)
I20260812 06:18:31.212755 24258 log.cc:1079] T 77cfd638a34e4ff9bee3b1e5e77ae600 P de1cb23db8cc4eae908d21d0d0236e49: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/77cfd638a34e4ff9bee3b1e5e77ae600/wal-000000006 (ops 27-31)
I20260812 06:18:31.212785 24258 log.cc:1079] T 77cfd638a34e4ff9bee3b1e5e77ae600 P de1cb23db8cc4eae908d21d0d0236e49: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/77cfd638a34e4ff9bee3b1e5e77ae600/wal-000000007 (ops 32-36)
I20260812 06:18:31.212812 24258 log.cc:1079] T 77cfd638a34e4ff9bee3b1e5e77ae600 P de1cb23db8cc4eae908d21d0d0236e49: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/77cfd638a34e4ff9bee3b1e5e77ae600/wal-000000008 (ops 37-41)
I20260812 06:18:31.212841 24258 log.cc:1079] T 77cfd638a34e4ff9bee3b1e5e77ae600 P de1cb23db8cc4eae908d21d0d0236e49: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/77cfd638a34e4ff9bee3b1e5e77ae600/wal-000000009 (ops 42-46)
I20260812 06:18:31.212870 24258 log.cc:1079] T 77cfd638a34e4ff9bee3b1e5e77ae600 P de1cb23db8cc4eae908d21d0d0236e49: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/77cfd638a34e4ff9bee3b1e5e77ae600/wal-000000010 (ops 47-51)
I20260812 06:18:31.212901 24258 log.cc:1079] T 77cfd638a34e4ff9bee3b1e5e77ae600 P de1cb23db8cc4eae908d21d0d0236e49: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/77cfd638a34e4ff9bee3b1e5e77ae600/wal-000000011 (ops 52-56)
I20260812 06:18:31.212931 24258 log.cc:1079] T 77cfd638a34e4ff9bee3b1e5e77ae600 P de1cb23db8cc4eae908d21d0d0236e49: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/77cfd638a34e4ff9bee3b1e5e77ae600/wal-000000012 (ops 57-60)
I20260812 06:18:31.212961 24258 log.cc:1079] T 77cfd638a34e4ff9bee3b1e5e77ae600 P de1cb23db8cc4eae908d21d0d0236e49: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/77cfd638a34e4ff9bee3b1e5e77ae600/wal-000000013 (ops 61-65)
I20260812 06:18:31.212992 24258 log.cc:1079] T 77cfd638a34e4ff9bee3b1e5e77ae600 P de1cb23db8cc4eae908d21d0d0236e49: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/77cfd638a34e4ff9bee3b1e5e77ae600/wal-000000014 (ops 66-70)
I20260812 06:18:31.213018 24258 log.cc:1079] T 77cfd638a34e4ff9bee3b1e5e77ae600 P de1cb23db8cc4eae908d21d0d0236e49: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/77cfd638a34e4ff9bee3b1e5e77ae600/wal-000000015 (ops 71-75)
I20260812 06:18:31.235538 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: LogGCOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.023s	user 0.001s	sys 0.020s Metrics: {}
I20260812 06:18:31.235973 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling UndoDeltaBlockGCOp(77cfd638a34e4ff9bee3b1e5e77ae600): 482 bytes on disk
I20260812 06:18:31.236487 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: UndoDeltaBlockGCOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":83,"lbm_reads_lt_1ms":4}
I20260812 06:18:31.237037 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600): perf score=2.188937
I20260812 06:18:31.257181 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.020s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5746,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:31.257627 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600): perf score=2.188937
I20260812 06:18:31.267304 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3602,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:31.267890 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling MajorDeltaCompactionOp(77cfd638a34e4ff9bee3b1e5e77ae600): perf score=1.000000
I20260812 06:18:31.460291 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: MajorDeltaCompactionOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.192s	user 0.121s	sys 0.068s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918334,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":2570,"lbm_read_time_us":11988,"lbm_reads_lt_1ms":674,"lbm_write_time_us":31857,"lbm_writes_lt_1ms":643,"mutex_wait_us":2150,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":9088,"thread_start_us":82,"threads_started":1,"update_count":3000}
I20260812 06:18:31.460893 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600): perf score=14.095187
I20260812 06:18:31.514106 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.053s	user 0.034s	sys 0.004s Metrics: {"bytes_written":16409906,"delete_count":0,"lbm_write_time_us":17823,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:31.514537 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600): perf score=2.188937
I20260812 06:18:31.524748 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.010s	user 0.000s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3639,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:31.525377 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling MajorDeltaCompactionOp(77cfd638a34e4ff9bee3b1e5e77ae600): perf score=1.000000
I20260812 06:18:31.689235 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: MajorDeltaCompactionOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.164s	user 0.105s	sys 0.053s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":159,"lbm_read_time_us":10455,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25698,"lbm_writes_lt_1ms":543,"mutex_wait_us":1,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5760,"update_count":2500}
I20260812 06:18:31.689739 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600): perf score=14.095187
I20260812 06:18:31.741909 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.052s	user 0.038s	sys 0.008s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":20840,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:31.742393 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600): perf score=2.188937
I20260812 06:18:31.752504 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3797,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:31.752923 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling MajorDeltaCompactionOp(77cfd638a34e4ff9bee3b1e5e77ae600): perf score=1.000000
I20260812 06:18:31.914992 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: MajorDeltaCompactionOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.162s	user 0.095s	sys 0.061s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":902,"lbm_read_time_us":11453,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27401,"lbm_writes_lt_1ms":543,"mutex_wait_us":281,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11136,"update_count":2500}
I20260812 06:18:31.915498 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600): perf score=14.095187
I20260812 06:18:31.970254 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.055s	user 0.035s	sys 0.011s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17269,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:31.970854 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600): perf score=2.188937
I20260812 06:18:31.981027 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3837,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:31.981530 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling MajorDeltaCompactionOp(77cfd638a34e4ff9bee3b1e5e77ae600): perf score=1.000000
I20260812 06:18:32.140210 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: MajorDeltaCompactionOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.158s	user 0.094s	sys 0.064s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":675,"lbm_read_time_us":12318,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26631,"lbm_writes_lt_1ms":543,"mutex_wait_us":251,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:32.140723 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600): perf score=10.126437
I20260812 06:18:32.182709 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.042s	user 0.029s	sys 0.010s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16533,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:32.183238 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600): perf score=2.188937
I20260812 06:18:32.212126 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.029s	user 0.010s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4624,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:32.212620 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600): perf score=2.188937
I20260812 06:18:32.222466 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.010s	user 0.003s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3744,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:32.222883 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling MajorDeltaCompactionOp(77cfd638a34e4ff9bee3b1e5e77ae600): perf score=1.000000
I20260812 06:18:32.384795 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: MajorDeltaCompactionOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.162s	user 0.121s	sys 0.039s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815804,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":301,"lbm_read_time_us":11422,"lbm_reads_lt_1ms":573,"lbm_write_time_us":26011,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:32.385378 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600): perf score=11.118625
I20260812 06:18:32.420758 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.035s	user 0.022s	sys 0.012s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":15161,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:32.421226 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600): perf score=2.188937
I20260812 06:18:32.437613 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.016s	user 0.004s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5309,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:32.438048 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling MajorDeltaCompactionOp(77cfd638a34e4ff9bee3b1e5e77ae600): perf score=1.000000
I20260812 06:18:32.561450 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: MajorDeltaCompactionOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.123s	user 0.105s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713264,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":173,"lbm_read_time_us":7296,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24661,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:32.562729 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600): perf score=11.118625
I20260812 06:18:32.594805 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.032s	user 0.021s	sys 0.008s Metrics: {"bytes_written":12676712,"delete_count":0,"lbm_write_time_us":13721,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1545}
I20260812 06:18:32.595568 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600): perf score=2.188937
I20260812 06:18:32.606716 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.011s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3733434,"delete_count":0,"lbm_write_time_us":3796,"lbm_writes_lt_1ms":94,"reinsert_count":0,"update_count":455}
I20260812 06:18:32.607218 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling FlushMRSOp(77cfd638a34e4ff9bee3b1e5e77ae600): perf score=1.000000
I20260812 06:18:32.635231 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: FlushMRSOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.028s	user 0.026s	sys 0.000s Metrics: {"bytes_written":1234477,"cfile_init":1,"dirs.queue_time_us":52,"dirs.run_cpu_time_us":208,"dirs.run_wall_time_us":1184,"drs_written":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1922,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:32.636052 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling LogGCOp(77cfd638a34e4ff9bee3b1e5e77ae600): free 121006514 bytes of WAL
I20260812 06:18:32.636286 24258 log_reader.cc:385] T 77cfd638a34e4ff9bee3b1e5e77ae600: removed 12 log segments from log reader
I20260812 06:18:32.636349 24258 log.cc:1079] T 77cfd638a34e4ff9bee3b1e5e77ae600 P de1cb23db8cc4eae908d21d0d0236e49: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/77cfd638a34e4ff9bee3b1e5e77ae600/wal-000000016 (ops 76-80)
I20260812 06:18:32.636394 24258 log.cc:1079] T 77cfd638a34e4ff9bee3b1e5e77ae600 P de1cb23db8cc4eae908d21d0d0236e49: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/77cfd638a34e4ff9bee3b1e5e77ae600/wal-000000017 (ops 81-85)
I20260812 06:18:32.636428 24258 log.cc:1079] T 77cfd638a34e4ff9bee3b1e5e77ae600 P de1cb23db8cc4eae908d21d0d0236e49: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/77cfd638a34e4ff9bee3b1e5e77ae600/wal-000000018 (ops 86-90)
I20260812 06:18:32.636451 24258 log.cc:1079] T 77cfd638a34e4ff9bee3b1e5e77ae600 P de1cb23db8cc4eae908d21d0d0236e49: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/77cfd638a34e4ff9bee3b1e5e77ae600/wal-000000019 (ops 91-95)
I20260812 06:18:32.636473 24258 log.cc:1079] T 77cfd638a34e4ff9bee3b1e5e77ae600 P de1cb23db8cc4eae908d21d0d0236e49: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/77cfd638a34e4ff9bee3b1e5e77ae600/wal-000000020 (ops 96-100)
I20260812 06:18:32.636500 24258 log.cc:1079] T 77cfd638a34e4ff9bee3b1e5e77ae600 P de1cb23db8cc4eae908d21d0d0236e49: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/77cfd638a34e4ff9bee3b1e5e77ae600/wal-000000021 (ops 101-104)
I20260812 06:18:32.636529 24258 log.cc:1079] T 77cfd638a34e4ff9bee3b1e5e77ae600 P de1cb23db8cc4eae908d21d0d0236e49: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/77cfd638a34e4ff9bee3b1e5e77ae600/wal-000000022 (ops 105-109)
I20260812 06:18:32.636560 24258 log.cc:1079] T 77cfd638a34e4ff9bee3b1e5e77ae600 P de1cb23db8cc4eae908d21d0d0236e49: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/77cfd638a34e4ff9bee3b1e5e77ae600/wal-000000023 (ops 110-114)
I20260812 06:18:32.636591 24258 log.cc:1079] T 77cfd638a34e4ff9bee3b1e5e77ae600 P de1cb23db8cc4eae908d21d0d0236e49: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/77cfd638a34e4ff9bee3b1e5e77ae600/wal-000000024 (ops 115-119)
I20260812 06:18:32.636618 24258 log.cc:1079] T 77cfd638a34e4ff9bee3b1e5e77ae600 P de1cb23db8cc4eae908d21d0d0236e49: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/77cfd638a34e4ff9bee3b1e5e77ae600/wal-000000025 (ops 120-124)
I20260812 06:18:32.636646 24258 log.cc:1079] T 77cfd638a34e4ff9bee3b1e5e77ae600 P de1cb23db8cc4eae908d21d0d0236e49: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/77cfd638a34e4ff9bee3b1e5e77ae600/wal-000000026 (ops 125-129)
I20260812 06:18:32.636672 24258 log.cc:1079] T 77cfd638a34e4ff9bee3b1e5e77ae600 P de1cb23db8cc4eae908d21d0d0236e49: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/77cfd638a34e4ff9bee3b1e5e77ae600/wal-000000027 (ops 130-134)
I20260812 06:18:32.662127 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: LogGCOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.026s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:18:32.662557 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling UndoDeltaBlockGCOp(77cfd638a34e4ff9bee3b1e5e77ae600): 473 bytes on disk
I20260812 06:18:32.663137 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: UndoDeltaBlockGCOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4}
I20260812 06:18:32.663640 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600): perf score=4.173312
I20260812 06:18:32.679771 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.016s	user 0.007s	sys 0.009s Metrics: {"bytes_written":5620560,"delete_count":0,"lbm_write_time_us":6237,"lbm_writes_lt_1ms":140,"reinsert_count":0,"update_count":685}
I20260812 06:18:32.680231 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600): perf score=1.196750
I20260812 06:18:32.693974 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.014s	user 0.005s	sys 0.004s Metrics: {"bytes_written":2584729,"delete_count":0,"lbm_write_time_us":4283,"lbm_writes_lt_1ms":66,"reinsert_count":0,"update_count":315}
I20260812 06:18:32.694444 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling MajorDeltaCompactionOp(77cfd638a34e4ff9bee3b1e5e77ae600): perf score=1.000000
I20260812 06:18:32.848778 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: MajorDeltaCompactionOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.154s	user 0.142s	sys 0.012s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918296,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":546,"lbm_read_time_us":10119,"lbm_reads_lt_1ms":666,"lbm_write_time_us":30455,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1280,"thread_start_us":79,"threads_started":1,"update_count":3000}
I20260812 06:18:32.849287 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600): perf score=14.095187
I20260812 06:18:32.894958 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.045s	user 0.028s	sys 0.011s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":18457,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:32.895501 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600): perf score=2.188937
I20260812 06:18:32.906697 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3944,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:32.907224 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling MajorDeltaCompactionOp(77cfd638a34e4ff9bee3b1e5e77ae600): perf score=1.000000
I20260812 06:18:33.071564 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: MajorDeltaCompactionOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.164s	user 0.117s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815679,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":178,"lbm_read_time_us":10404,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30833,"lbm_writes_lt_1ms":543,"mutex_wait_us":41,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7936,"update_count":2500}
I20260812 06:18:33.072119 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600): perf score=14.095187
I20260812 06:18:33.116843 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.045s	user 0.020s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17733,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:33.117409 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600): perf score=2.188937
I20260812 06:18:33.127334 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3793,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:33.127890 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling MajorDeltaCompactionOp(77cfd638a34e4ff9bee3b1e5e77ae600): perf score=1.000000
I20260812 06:18:33.278168 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: MajorDeltaCompactionOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.150s	user 0.103s	sys 0.042s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":208,"lbm_read_time_us":9709,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29736,"lbm_writes_lt_1ms":543,"mutex_wait_us":30,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2500}
I20260812 06:18:33.278760 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600): perf score=11.118625
I20260812 06:18:33.321484 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.043s	user 0.028s	sys 0.007s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16204,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:33.322103 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600): perf score=2.188937
I20260812 06:18:33.335909 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.014s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5401,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:33.336380 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600): perf score=2.188937
I20260812 06:18:33.349900 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.013s	user 0.002s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4685,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:33.350659 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling MajorDeltaCompactionOp(77cfd638a34e4ff9bee3b1e5e77ae600): perf score=1.000000
I20260812 06:18:33.507668 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: MajorDeltaCompactionOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.157s	user 0.119s	sys 0.032s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815794,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":329,"dirs.run_cpu_time_us":688,"dirs.run_wall_time_us":3213,"lbm_read_time_us":9178,"lbm_reads_lt_1ms":573,"lbm_write_time_us":28703,"lbm_writes_lt_1ms":543,"mutex_wait_us":75,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2500}
I20260812 06:18:33.508227 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600): perf score=10.126437
I20260812 06:18:33.550241 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.042s	user 0.022s	sys 0.014s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":17000,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:33.550763 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600): perf score=2.188937
I20260812 06:18:33.565331 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.014s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5471,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:33.565825 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling MajorDeltaCompactionOp(77cfd638a34e4ff9bee3b1e5e77ae600): perf score=1.000000
I20260812 06:18:33.705108 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: MajorDeltaCompactionOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.139s	user 0.119s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713274,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1015,"lbm_read_time_us":11790,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21578,"lbm_writes_lt_1ms":443,"mutex_wait_us":290,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:18:33.705698 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600): perf score=10.126437
I20260812 06:18:33.740991 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.035s	user 0.027s	sys 0.004s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":14050,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:33.741474 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600): perf score=2.188937
I20260812 06:18:33.751333 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3746,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:33.751856 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling MajorDeltaCompactionOp(77cfd638a34e4ff9bee3b1e5e77ae600): perf score=1.000000
I20260812 06:18:33.889953 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: MajorDeltaCompactionOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.138s	user 0.093s	sys 0.041s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713271,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1131,"lbm_read_time_us":8323,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24294,"lbm_writes_lt_1ms":443,"mutex_wait_us":308,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:33.890551 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600): perf score=10.126437
I20260812 06:18:33.931488 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.041s	user 0.023s	sys 0.015s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":17645,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:33.932035 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600): perf score=2.188937
I20260812 06:18:33.942459 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3708,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:33.942898 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling FlushMRSOp(77cfd638a34e4ff9bee3b1e5e77ae600): perf score=1.000000
I20260812 06:18:33.969986 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: FlushMRSOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.027s	user 0.025s	sys 0.000s Metrics: {"bytes_written":1193507,"cfile_init":1,"dirs.queue_time_us":55,"dirs.run_cpu_time_us":215,"dirs.run_wall_time_us":1314,"drs_written":1,"lbm_read_time_us":46,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1482,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:33.970777 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling LogGCOp(77cfd638a34e4ff9bee3b1e5e77ae600): free 124257510 bytes of WAL
I20260812 06:18:33.971057 24258 log_reader.cc:385] T 77cfd638a34e4ff9bee3b1e5e77ae600: removed 12 log segments from log reader
I20260812 06:18:33.971112 24258 log.cc:1079] T 77cfd638a34e4ff9bee3b1e5e77ae600 P de1cb23db8cc4eae908d21d0d0236e49: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/77cfd638a34e4ff9bee3b1e5e77ae600/wal-000000028 (ops 135-139)
I20260812 06:18:33.971151 24258 log.cc:1079] T 77cfd638a34e4ff9bee3b1e5e77ae600 P de1cb23db8cc4eae908d21d0d0236e49: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/77cfd638a34e4ff9bee3b1e5e77ae600/wal-000000029 (ops 140-144)
I20260812 06:18:33.971182 24258 log.cc:1079] T 77cfd638a34e4ff9bee3b1e5e77ae600 P de1cb23db8cc4eae908d21d0d0236e49: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/77cfd638a34e4ff9bee3b1e5e77ae600/wal-000000030 (ops 145-148)
I20260812 06:18:33.971207 24258 log.cc:1079] T 77cfd638a34e4ff9bee3b1e5e77ae600 P de1cb23db8cc4eae908d21d0d0236e49: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/77cfd638a34e4ff9bee3b1e5e77ae600/wal-000000031 (ops 149-153)
I20260812 06:18:33.971238 24258 log.cc:1079] T 77cfd638a34e4ff9bee3b1e5e77ae600 P de1cb23db8cc4eae908d21d0d0236e49: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/77cfd638a34e4ff9bee3b1e5e77ae600/wal-000000032 (ops 154-158)
I20260812 06:18:33.971267 24258 log.cc:1079] T 77cfd638a34e4ff9bee3b1e5e77ae600 P de1cb23db8cc4eae908d21d0d0236e49: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/77cfd638a34e4ff9bee3b1e5e77ae600/wal-000000033 (ops 159-163)
I20260812 06:18:33.971325 24258 log.cc:1079] T 77cfd638a34e4ff9bee3b1e5e77ae600 P de1cb23db8cc4eae908d21d0d0236e49: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/77cfd638a34e4ff9bee3b1e5e77ae600/wal-000000034 (ops 164-168)
I20260812 06:18:33.971360 24258 log.cc:1079] T 77cfd638a34e4ff9bee3b1e5e77ae600 P de1cb23db8cc4eae908d21d0d0236e49: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/77cfd638a34e4ff9bee3b1e5e77ae600/wal-000000035 (ops 169-173)
I20260812 06:18:33.971390 24258 log.cc:1079] T 77cfd638a34e4ff9bee3b1e5e77ae600 P de1cb23db8cc4eae908d21d0d0236e49: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/77cfd638a34e4ff9bee3b1e5e77ae600/wal-000000036 (ops 174-178)
I20260812 06:18:33.971419 24258 log.cc:1079] T 77cfd638a34e4ff9bee3b1e5e77ae600 P de1cb23db8cc4eae908d21d0d0236e49: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/77cfd638a34e4ff9bee3b1e5e77ae600/wal-000000037 (ops 179-183)
I20260812 06:18:33.971448 24258 log.cc:1079] T 77cfd638a34e4ff9bee3b1e5e77ae600 P de1cb23db8cc4eae908d21d0d0236e49: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/77cfd638a34e4ff9bee3b1e5e77ae600/wal-000000038 (ops 184-188)
I20260812 06:18:33.971477 24258 log.cc:1079] T 77cfd638a34e4ff9bee3b1e5e77ae600 P de1cb23db8cc4eae908d21d0d0236e49: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/77cfd638a34e4ff9bee3b1e5e77ae600/wal-000000039 (ops 189-193)
I20260812 06:18:33.996058 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: LogGCOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.025s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:18:33.996523 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling UndoDeltaBlockGCOp(77cfd638a34e4ff9bee3b1e5e77ae600): 462 bytes on disk
I20260812 06:18:33.997010 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: UndoDeltaBlockGCOp(77cfd638a34e4ff9bee3b1e5e77ae600) 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:33.997764 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600): perf score=4.173312
I20260812 06:18:34.014662 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.017s	user 0.000s	sys 0.015s Metrics: {"bytes_written":5415440,"delete_count":0,"lbm_write_time_us":6860,"lbm_writes_lt_1ms":135,"reinsert_count":0,"update_count":660}
I20260812 06:18:34.015062 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600): perf score=1.196750
I20260812 06:18:34.023397 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.008s	user 0.002s	sys 0.004s Metrics: {"bytes_written":2789855,"delete_count":0,"lbm_write_time_us":2560,"lbm_writes_lt_1ms":71,"reinsert_count":0,"update_count":340}
I20260812 06:18:34.023887 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling MajorDeltaCompactionOp(77cfd638a34e4ff9bee3b1e5e77ae600): perf score=1.000000
I20260812 06:18:34.144997 24067 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.519s	user 1.652s	sys 0.140s
I20260812 06:18:34.185158 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: MajorDeltaCompactionOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.161s	user 0.107s	sys 0.053s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918304,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":12998,"lbm_reads_lt_1ms":670,"lbm_write_time_us":32537,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":4992,"update_count":3000}
I20260812 06:18:34.185731 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600): perf score=10.126437
I20260812 06:18:34.215842 24067 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.070s	user 0.004s	sys 0.000s
I20260812 06:18:34.216454 24067 tablet_server.cc:179] TabletServer@127.23.128.193:0 shutting down...
I20260812 06:18:34.220669 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: FlushDeltaMemStoresOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.035s	user 0.030s	sys 0.003s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14348,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:34.221513 24376 maintenance_manager.cc:419] P de1cb23db8cc4eae908d21d0d0236e49: Scheduling MajorDeltaCompactionOp(77cfd638a34e4ff9bee3b1e5e77ae600): perf score=1.000000
I20260812 06:18:34.310325 24258 maintenance_manager.cc:643] P de1cb23db8cc4eae908d21d0d0236e49: MajorDeltaCompactionOp(77cfd638a34e4ff9bee3b1e5e77ae600) complete. Timing: real 0.089s	user 0.069s	sys 0.020s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16610741,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":378,"lbm_read_time_us":6035,"lbm_reads_lt_1ms":367,"lbm_write_time_us":15013,"lbm_writes_lt_1ms":343,"mutex_wait_us":44,"peak_mem_usage":38262756,"reinsert_count":0,"update_count":1500}
I20260812 06:18:34.311470 24067 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:34.311904 24067 tablet_replica.cc:333] T 77cfd638a34e4ff9bee3b1e5e77ae600 P de1cb23db8cc4eae908d21d0d0236e49: stopping tablet replica
I20260812 06:18:34.312131 24067 raft_consensus.cc:2243] T 77cfd638a34e4ff9bee3b1e5e77ae600 P de1cb23db8cc4eae908d21d0d0236e49 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:34.312371 24067 raft_consensus.cc:2272] T 77cfd638a34e4ff9bee3b1e5e77ae600 P de1cb23db8cc4eae908d21d0d0236e49 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:34.328683 24067 tablet_server.cc:196] TabletServer@127.23.128.193:0 shutdown complete.
I20260812 06:18:34.342052 24067 master.cc:562] Master@127.23.128.254:33315 shutting down...
I20260812 06:18:34.345727 24067 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 98af9c9f38184667a97b077a0c3b7f82 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:34.345881 24067 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 98af9c9f38184667a97b077a0c3b7f82 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:34.345933 24067 tablet_replica.cc:333] T 00000000000000000000000000000000 P 98af9c9f38184667a97b077a0c3b7f82: stopping tablet replica
I20260812 06:18:34.357995 24067 master.cc:584] Master@127.23.128.254:33315 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5073 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:34.431819 24067 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.23.128.254:37291
I20260812 06:18:34.432173 24067 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:34.434073 24418 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:34.434069 24417 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:34.434194 24420 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:34.434254 24067 server_base.cc:1061] running on GCE node
I20260812 06:18:34.434394 24067 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:34.434450 24067 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:34.434469 24067 hybrid_clock.cc:648] HybridClock initialized: now 1786515514434469 us; error 0 us; skew 500 ppm
I20260812 06:18:34.435292 24067 webserver.cc:533] Webserver started at http://127.23.128.254:43309/ using document root <none> and password file <none>
I20260812 06:18:34.435479 24067 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:34.435527 24067 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:34.435603 24067 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:34.436008 24067 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515509348364-24067-0/minicluster-data/master-0-root/instance:
uuid: "63f636c9452e49ea8411d504257d7673"
format_stamp: "Formatted at 2026-08-12 06:18:34 on dist-test-slave-1l3l"
I20260812 06:18:34.437395 24067 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:34.438279 24427 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:34.438483 24067 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:34.438548 24067 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515509348364-24067-0/minicluster-data/master-0-root
uuid: "63f636c9452e49ea8411d504257d7673"
format_stamp: "Formatted at 2026-08-12 06:18:34 on dist-test-slave-1l3l"
I20260812 06:18:34.438616 24067 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515509348364-24067-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515509348364-24067-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515509348364-24067-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:34.450243 24067 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:34.450584 24067 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:34.454566 24067 rpc_server.cc:307] RPC server started. Bound to: 127.23.128.254:37291
I20260812 06:18:34.463313 24522 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.23.128.254:37291 every 8 connection(s)
I20260812 06:18:34.463800 24523 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:34.465520 24523 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 63f636c9452e49ea8411d504257d7673: Bootstrap starting.
I20260812 06:18:34.466238 24523 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 63f636c9452e49ea8411d504257d7673: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:34.467113 24523 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 63f636c9452e49ea8411d504257d7673: No bootstrap required, opened a new log
I20260812 06:18:34.467468 24523 raft_consensus.cc:359] T 00000000000000000000000000000000 P 63f636c9452e49ea8411d504257d7673 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "63f636c9452e49ea8411d504257d7673" member_type: VOTER }
I20260812 06:18:34.467549 24523 raft_consensus.cc:385] T 00000000000000000000000000000000 P 63f636c9452e49ea8411d504257d7673 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:34.467576 24523 raft_consensus.cc:740] T 00000000000000000000000000000000 P 63f636c9452e49ea8411d504257d7673 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 63f636c9452e49ea8411d504257d7673, State: Initialized, Role: FOLLOWER
I20260812 06:18:34.467693 24523 consensus_queue.cc:260] T 00000000000000000000000000000000 P 63f636c9452e49ea8411d504257d7673 [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: "63f636c9452e49ea8411d504257d7673" member_type: VOTER }
I20260812 06:18:34.467803 24523 raft_consensus.cc:399] T 00000000000000000000000000000000 P 63f636c9452e49ea8411d504257d7673 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:34.467832 24523 raft_consensus.cc:493] T 00000000000000000000000000000000 P 63f636c9452e49ea8411d504257d7673 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:34.467867 24523 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 63f636c9452e49ea8411d504257d7673 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:34.468529 24523 raft_consensus.cc:515] T 00000000000000000000000000000000 P 63f636c9452e49ea8411d504257d7673 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "63f636c9452e49ea8411d504257d7673" member_type: VOTER }
I20260812 06:18:34.468641 24523 leader_election.cc:304] T 00000000000000000000000000000000 P 63f636c9452e49ea8411d504257d7673 [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: 63f636c9452e49ea8411d504257d7673; no voters: 
I20260812 06:18:34.468780 24523 leader_election.cc:290] T 00000000000000000000000000000000 P 63f636c9452e49ea8411d504257d7673 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:34.468900 24526 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 63f636c9452e49ea8411d504257d7673 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:34.469084 24526 raft_consensus.cc:697] T 00000000000000000000000000000000 P 63f636c9452e49ea8411d504257d7673 [term 1 LEADER]: Becoming Leader. State: Replica: 63f636c9452e49ea8411d504257d7673, State: Running, Role: LEADER
I20260812 06:18:34.469230 24523 sys_catalog.cc:565] T 00000000000000000000000000000000 P 63f636c9452e49ea8411d504257d7673 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:34.469221 24526 consensus_queue.cc:237] T 00000000000000000000000000000000 P 63f636c9452e49ea8411d504257d7673 [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: "63f636c9452e49ea8411d504257d7673" member_type: VOTER }
I20260812 06:18:34.469655 24529 sys_catalog.cc:455] T 00000000000000000000000000000000 P 63f636c9452e49ea8411d504257d7673 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 63f636c9452e49ea8411d504257d7673. Latest consensus state: current_term: 1 leader_uuid: "63f636c9452e49ea8411d504257d7673" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "63f636c9452e49ea8411d504257d7673" member_type: VOTER } }
I20260812 06:18:34.469640 24527 sys_catalog.cc:455] T 00000000000000000000000000000000 P 63f636c9452e49ea8411d504257d7673 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "63f636c9452e49ea8411d504257d7673" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "63f636c9452e49ea8411d504257d7673" member_type: VOTER } }
I20260812 06:18:34.469776 24529 sys_catalog.cc:458] T 00000000000000000000000000000000 P 63f636c9452e49ea8411d504257d7673 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:34.469846 24527 sys_catalog.cc:458] T 00000000000000000000000000000000 P 63f636c9452e49ea8411d504257d7673 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:34.470422 24536 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:34.471165 24536 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:34.471309 24067 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:34.472821 24536 catalog_manager.cc:1383] Generated new cluster ID: bf6dedec5297469eb743f508f3f320a2
I20260812 06:18:34.472877 24536 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:34.481894 24536 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:34.482400 24536 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:34.487736 24536 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 63f636c9452e49ea8411d504257d7673: Generated new TSK 0
I20260812 06:18:34.487890 24536 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:34.503469 24067 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:34.505344 24560 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:34.505437 24561 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:34.505335 24565 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:34.505367 24067 server_base.cc:1061] running on GCE node
I20260812 06:18:34.505661 24067 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:34.505697 24067 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:34.505709 24067 hybrid_clock.cc:648] HybridClock initialized: now 1786515514505710 us; error 0 us; skew 500 ppm
I20260812 06:18:34.506471 24067 webserver.cc:533] Webserver started at http://127.23.128.193:33845/ using document root <none> and password file <none>
I20260812 06:18:34.506621 24067 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:34.506670 24067 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:34.506745 24067 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:34.507113 24067 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515509348364-24067-0/minicluster-data/ts-0-root/instance:
uuid: "6d7f95c1981141c389bf9cd807d44979"
format_stamp: "Formatted at 2026-08-12 06:18:34 on dist-test-slave-1l3l"
I20260812 06:18:34.508824 24067 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:34.509684 24575 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:34.509874 24067 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:34.509940 24067 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515509348364-24067-0/minicluster-data/ts-0-root
uuid: "6d7f95c1981141c389bf9cd807d44979"
format_stamp: "Formatted at 2026-08-12 06:18:34 on dist-test-slave-1l3l"
I20260812 06:18:34.510015 24067 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515509348364-24067-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515509348364-24067-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515509348364-24067-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:34.521939 24067 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:34.522245 24067 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:34.522554 24067 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:34.522992 24067 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:34.523037 24067 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:34.523080 24067 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:34.523108 24067 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:34.527069 24067 rpc_server.cc:307] RPC server started. Bound to: 127.23.128.193:46199
I20260812 06:18:34.527092 24682 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.23.128.193:46199 every 8 connection(s)
I20260812 06:18:34.534466 24683 heartbeater.cc:344] Connected to a master server at 127.23.128.254:37291
I20260812 06:18:34.534567 24683 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:34.534773 24683 heartbeater.cc:507] Master 127.23.128.254:37291 requested a full tablet report, sending...
I20260812 06:18:34.535398 24453 ts_manager.cc:194] Registered new tserver with Master: 6d7f95c1981141c389bf9cd807d44979 (127.23.128.193:46199)
I20260812 06:18:34.536146 24453 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:41940
I20260812 06:18:34.536157 24067 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.008751124s
I20260812 06:18:34.542361 24453 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:41944:
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:34.550127 24624 tablet_service.cc:1511] Processing CreateTablet for tablet 88484e6ebd7d4b43ac80c8c8d548c828 (DEFAULT_TABLE table=heavy-update-compaction-test [id=8006aa8645ac40a496876c49024cc789]), partition=
I20260812 06:18:34.550383 24624 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 88484e6ebd7d4b43ac80c8c8d548c828. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:34.552340 24705 tablet_bootstrap.cc:492] T 88484e6ebd7d4b43ac80c8c8d548c828 P 6d7f95c1981141c389bf9cd807d44979: Bootstrap starting.
I20260812 06:18:34.553231 24705 tablet_bootstrap.cc:654] T 88484e6ebd7d4b43ac80c8c8d548c828 P 6d7f95c1981141c389bf9cd807d44979: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:34.554191 24705 tablet_bootstrap.cc:492] T 88484e6ebd7d4b43ac80c8c8d548c828 P 6d7f95c1981141c389bf9cd807d44979: No bootstrap required, opened a new log
I20260812 06:18:34.554270 24705 ts_tablet_manager.cc:1403] T 88484e6ebd7d4b43ac80c8c8d548c828 P 6d7f95c1981141c389bf9cd807d44979: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:18:34.554656 24705 raft_consensus.cc:359] T 88484e6ebd7d4b43ac80c8c8d548c828 P 6d7f95c1981141c389bf9cd807d44979 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6d7f95c1981141c389bf9cd807d44979" member_type: VOTER last_known_addr { host: "127.23.128.193" port: 46199 } }
I20260812 06:18:34.554737 24705 raft_consensus.cc:385] T 88484e6ebd7d4b43ac80c8c8d548c828 P 6d7f95c1981141c389bf9cd807d44979 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:34.554768 24705 raft_consensus.cc:740] T 88484e6ebd7d4b43ac80c8c8d548c828 P 6d7f95c1981141c389bf9cd807d44979 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 6d7f95c1981141c389bf9cd807d44979, State: Initialized, Role: FOLLOWER
I20260812 06:18:34.554895 24705 consensus_queue.cc:260] T 88484e6ebd7d4b43ac80c8c8d548c828 P 6d7f95c1981141c389bf9cd807d44979 [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: "6d7f95c1981141c389bf9cd807d44979" member_type: VOTER last_known_addr { host: "127.23.128.193" port: 46199 } }
I20260812 06:18:34.554966 24705 raft_consensus.cc:399] T 88484e6ebd7d4b43ac80c8c8d548c828 P 6d7f95c1981141c389bf9cd807d44979 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:34.555006 24705 raft_consensus.cc:493] T 88484e6ebd7d4b43ac80c8c8d548c828 P 6d7f95c1981141c389bf9cd807d44979 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:34.555051 24705 raft_consensus.cc:3060] T 88484e6ebd7d4b43ac80c8c8d548c828 P 6d7f95c1981141c389bf9cd807d44979 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:34.555882 24705 raft_consensus.cc:515] T 88484e6ebd7d4b43ac80c8c8d548c828 P 6d7f95c1981141c389bf9cd807d44979 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6d7f95c1981141c389bf9cd807d44979" member_type: VOTER last_known_addr { host: "127.23.128.193" port: 46199 } }
I20260812 06:18:34.556015 24705 leader_election.cc:304] T 88484e6ebd7d4b43ac80c8c8d548c828 P 6d7f95c1981141c389bf9cd807d44979 [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: 6d7f95c1981141c389bf9cd807d44979; no voters: 
I20260812 06:18:34.556208 24705 leader_election.cc:290] T 88484e6ebd7d4b43ac80c8c8d548c828 P 6d7f95c1981141c389bf9cd807d44979 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:34.556313 24709 raft_consensus.cc:2804] T 88484e6ebd7d4b43ac80c8c8d548c828 P 6d7f95c1981141c389bf9cd807d44979 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:34.556489 24705 ts_tablet_manager.cc:1434] T 88484e6ebd7d4b43ac80c8c8d548c828 P 6d7f95c1981141c389bf9cd807d44979: Time spent starting tablet: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:18:34.556521 24709 raft_consensus.cc:697] T 88484e6ebd7d4b43ac80c8c8d548c828 P 6d7f95c1981141c389bf9cd807d44979 [term 1 LEADER]: Becoming Leader. State: Replica: 6d7f95c1981141c389bf9cd807d44979, State: Running, Role: LEADER
I20260812 06:18:34.556509 24683 heartbeater.cc:499] Master 127.23.128.254:37291 was elected leader, sending a full tablet report...
I20260812 06:18:34.556737 24709 consensus_queue.cc:237] T 88484e6ebd7d4b43ac80c8c8d548c828 P 6d7f95c1981141c389bf9cd807d44979 [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: "6d7f95c1981141c389bf9cd807d44979" member_type: VOTER last_known_addr { host: "127.23.128.193" port: 46199 } }
I20260812 06:18:34.557931 24453 catalog_manager.cc:5719] T 88484e6ebd7d4b43ac80c8c8d548c828 P 6d7f95c1981141c389bf9cd807d44979 reported cstate change: term changed from 0 to 1, leader changed from <none> to 6d7f95c1981141c389bf9cd807d44979 (127.23.128.193). New cstate: current_term: 1 leader_uuid: "6d7f95c1981141c389bf9cd807d44979" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6d7f95c1981141c389bf9cd807d44979" member_type: VOTER last_known_addr { host: "127.23.128.193" port: 46199 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:34.609445 24067 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.048s	user 0.012s	sys 0.008s
I20260812 06:18:34.778015 24684 maintenance_manager.cc:419] P 6d7f95c1981141c389bf9cd807d44979: Scheduling FlushMRSOp(88484e6ebd7d4b43ac80c8c8d548c828): perf score=23.023690
I20260812 06:18:34.928021 24584 maintenance_manager.cc:643] P 6d7f95c1981141c389bf9cd807d44979: FlushMRSOp(88484e6ebd7d4b43ac80c8c8d548c828) complete. Timing: real 0.150s	user 0.124s	sys 0.024s Metrics: {"bytes_written":12881835,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":57,"dirs.run_cpu_time_us":159,"dirs.run_wall_time_us":726,"drs_written":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4,"lbm_write_time_us":38595,"lbm_writes_lt_1ms":871,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"spinlock_wait_cycles":12672,"update_count":1570}
I20260812 06:18:34.928750 24684 maintenance_manager.cc:419] P 6d7f95c1981141c389bf9cd807d44979: Scheduling LogGCOp(88484e6ebd7d4b43ac80c8c8d548c828): free 20290830 bytes of WAL
I20260812 06:18:34.928968 24584 log_reader.cc:385] T 88484e6ebd7d4b43ac80c8c8d548c828: removed 2 log segments from log reader
I20260812 06:18:34.929031 24584 log.cc:1079] T 88484e6ebd7d4b43ac80c8c8d548c828 P 6d7f95c1981141c389bf9cd807d44979: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/88484e6ebd7d4b43ac80c8c8d548c828/wal-000000001 (ops 1-6)
I20260812 06:18:34.929073 24584 log.cc:1079] T 88484e6ebd7d4b43ac80c8c8d548c828 P 6d7f95c1981141c389bf9cd807d44979: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/88484e6ebd7d4b43ac80c8c8d548c828/wal-000000002 (ops 7-10)
I20260812 06:18:34.933332 24584 maintenance_manager.cc:643] P 6d7f95c1981141c389bf9cd807d44979: LogGCOp(88484e6ebd7d4b43ac80c8c8d548c828) complete. Timing: real 0.004s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:18:34.933703 24684 maintenance_manager.cc:419] P 6d7f95c1981141c389bf9cd807d44979: Scheduling UndoDeltaBlockGCOp(88484e6ebd7d4b43ac80c8c8d548c828): 20513813 bytes on disk
I20260812 06:18:34.934094 24584 maintenance_manager.cc:643] P 6d7f95c1981141c389bf9cd807d44979: UndoDeltaBlockGCOp(88484e6ebd7d4b43ac80c8c8d548c828) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4}
I20260812 06:18:34.934494 24684 maintenance_manager.cc:419] P 6d7f95c1981141c389bf9cd807d44979: Scheduling FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828): perf score=2.188937
I20260812 06:18:34.954154 24584 maintenance_manager.cc:643] P 6d7f95c1981141c389bf9cd807d44979: FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828) complete. Timing: real 0.020s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3938559,"delete_count":0,"lbm_write_time_us":5953,"lbm_writes_lt_1ms":99,"reinsert_count":0,"update_count":480}
I20260812 06:18:34.954569 24684 maintenance_manager.cc:419] P 6d7f95c1981141c389bf9cd807d44979: Scheduling FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828): perf score=2.188937
I20260812 06:18:34.967373 24584 maintenance_manager.cc:643] P 6d7f95c1981141c389bf9cd807d44979: FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4869,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:34.967854 24684 maintenance_manager.cc:419] P 6d7f95c1981141c389bf9cd807d44979: Scheduling MajorDeltaCompactionOp(88484e6ebd7d4b43ac80c8c8d548c828): perf score=1.000000
I20260812 06:18:35.131062 24584 maintenance_manager.cc:643] P 6d7f95c1981141c389bf9cd807d44979: MajorDeltaCompactionOp(88484e6ebd7d4b43ac80c8c8d548c828) complete. Timing: real 0.163s	user 0.126s	sys 0.032s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815794,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":445,"lbm_read_time_us":11463,"lbm_reads_lt_1ms":569,"lbm_write_time_us":29191,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2688,"thread_start_us":292,"threads_started":5,"update_count":2500}
I20260812 06:18:35.131641 24684 maintenance_manager.cc:419] P 6d7f95c1981141c389bf9cd807d44979: Scheduling FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828): perf score=11.118625
I20260812 06:18:35.169922 24584 maintenance_manager.cc:643] P 6d7f95c1981141c389bf9cd807d44979: FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828) complete. Timing: real 0.038s	user 0.021s	sys 0.013s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":15655,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:18:35.170559 24684 maintenance_manager.cc:419] P 6d7f95c1981141c389bf9cd807d44979: Scheduling FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828): perf score=2.188937
I20260812 06:18:35.184752 24584 maintenance_manager.cc:643] P 6d7f95c1981141c389bf9cd807d44979: FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828) complete. Timing: real 0.014s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4163,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:35.185254 24684 maintenance_manager.cc:419] P 6d7f95c1981141c389bf9cd807d44979: Scheduling FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828): perf score=2.188937
I20260812 06:18:35.194115 24584 maintenance_manager.cc:643] P 6d7f95c1981141c389bf9cd807d44979: FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828) complete. Timing: real 0.009s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3203,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:35.194640 24684 maintenance_manager.cc:419] P 6d7f95c1981141c389bf9cd807d44979: Scheduling MajorDeltaCompactionOp(88484e6ebd7d4b43ac80c8c8d548c828): perf score=1.000000
I20260812 06:18:35.353602 24584 maintenance_manager.cc:643] P 6d7f95c1981141c389bf9cd807d44979: MajorDeltaCompactionOp(88484e6ebd7d4b43ac80c8c8d548c828) complete. Timing: real 0.159s	user 0.127s	sys 0.015s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815795,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":253,"lbm_read_time_us":9752,"lbm_reads_lt_1ms":573,"lbm_write_time_us":28333,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":2500}
I20260812 06:18:35.354097 24684 maintenance_manager.cc:419] P 6d7f95c1981141c389bf9cd807d44979: Scheduling FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828): perf score=14.095187
I20260812 06:18:35.395681 24584 maintenance_manager.cc:643] P 6d7f95c1981141c389bf9cd807d44979: FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828) complete. Timing: real 0.041s	user 0.029s	sys 0.008s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18156,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:35.396199 24684 maintenance_manager.cc:419] P 6d7f95c1981141c389bf9cd807d44979: Scheduling MajorDeltaCompactionOp(88484e6ebd7d4b43ac80c8c8d548c828): perf score=1.000000
I20260812 06:18:35.544389 24584 maintenance_manager.cc:643] P 6d7f95c1981141c389bf9cd807d44979: MajorDeltaCompactionOp(88484e6ebd7d4b43ac80c8c8d548c828) complete. Timing: real 0.148s	user 0.096s	sys 0.049s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713152,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":534,"lbm_read_time_us":10263,"lbm_reads_lt_1ms":463,"lbm_write_time_us":24900,"lbm_writes_lt_1ms":443,"mutex_wait_us":307,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:35.544816 24684 maintenance_manager.cc:419] P 6d7f95c1981141c389bf9cd807d44979: Scheduling FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828): perf score=14.095187
I20260812 06:18:35.599081 24584 maintenance_manager.cc:643] P 6d7f95c1981141c389bf9cd807d44979: FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828) complete. Timing: real 0.054s	user 0.032s	sys 0.015s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":17863,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:35.599620 24684 maintenance_manager.cc:419] P 6d7f95c1981141c389bf9cd807d44979: Scheduling FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828): perf score=2.188937
I20260812 06:18:35.614253 24584 maintenance_manager.cc:643] P 6d7f95c1981141c389bf9cd807d44979: FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5581,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:35.614734 24684 maintenance_manager.cc:419] P 6d7f95c1981141c389bf9cd807d44979: Scheduling MajorDeltaCompactionOp(88484e6ebd7d4b43ac80c8c8d548c828): perf score=1.000000
I20260812 06:18:35.794322 24584 maintenance_manager.cc:643] P 6d7f95c1981141c389bf9cd807d44979: MajorDeltaCompactionOp(88484e6ebd7d4b43ac80c8c8d548c828) complete. Timing: real 0.179s	user 0.103s	sys 0.064s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":750,"lbm_read_time_us":12237,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27412,"lbm_writes_lt_1ms":543,"mutex_wait_us":38,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9472,"update_count":2500}
I20260812 06:18:35.794914 24684 maintenance_manager.cc:419] P 6d7f95c1981141c389bf9cd807d44979: Scheduling FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828): perf score=14.095187
I20260812 06:18:35.856957 24584 maintenance_manager.cc:643] P 6d7f95c1981141c389bf9cd807d44979: FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828) complete. Timing: real 0.062s	user 0.041s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20593,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:35.857470 24684 maintenance_manager.cc:419] P 6d7f95c1981141c389bf9cd807d44979: Scheduling FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828): perf score=2.188937
I20260812 06:18:35.872393 24584 maintenance_manager.cc:643] P 6d7f95c1981141c389bf9cd807d44979: FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828) complete. Timing: real 0.015s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5621,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:35.872896 24684 maintenance_manager.cc:419] P 6d7f95c1981141c389bf9cd807d44979: Scheduling MajorDeltaCompactionOp(88484e6ebd7d4b43ac80c8c8d548c828): perf score=1.000000
I20260812 06:18:36.058171 24584 maintenance_manager.cc:643] P 6d7f95c1981141c389bf9cd807d44979: MajorDeltaCompactionOp(88484e6ebd7d4b43ac80c8c8d548c828) complete. Timing: real 0.185s	user 0.107s	sys 0.068s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":848,"lbm_read_time_us":12672,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27647,"lbm_writes_lt_1ms":543,"mutex_wait_us":305,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":15616,"update_count":2500}
I20260812 06:18:36.058897 24684 maintenance_manager.cc:419] P 6d7f95c1981141c389bf9cd807d44979: Scheduling FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828): perf score=14.095187
I20260812 06:18:36.105188 24584 maintenance_manager.cc:643] P 6d7f95c1981141c389bf9cd807d44979: FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828) complete. Timing: real 0.046s	user 0.021s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19819,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:36.105760 24684 maintenance_manager.cc:419] P 6d7f95c1981141c389bf9cd807d44979: Scheduling FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828): perf score=2.188937
I20260812 06:18:36.129201 24584 maintenance_manager.cc:643] P 6d7f95c1981141c389bf9cd807d44979: FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828) complete. Timing: real 0.023s	user 0.011s	sys 0.010s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6400,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:36.129709 24684 maintenance_manager.cc:419] P 6d7f95c1981141c389bf9cd807d44979: Scheduling FlushMRSOp(88484e6ebd7d4b43ac80c8c8d548c828): perf score=1.000000
I20260812 06:18:36.170040 24584 maintenance_manager.cc:643] P 6d7f95c1981141c389bf9cd807d44979: FlushMRSOp(88484e6ebd7d4b43ac80c8c8d548c828) complete. Timing: real 0.040s	user 0.025s	sys 0.000s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":59,"dirs.run_cpu_time_us":223,"dirs.run_wall_time_us":1272,"drs_written":1,"lbm_read_time_us":46,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1813,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:36.170753 24684 maintenance_manager.cc:419] P 6d7f95c1981141c389bf9cd807d44979: Scheduling LogGCOp(88484e6ebd7d4b43ac80c8c8d548c828): free 121006421 bytes of WAL
I20260812 06:18:36.171046 24584 log_reader.cc:385] T 88484e6ebd7d4b43ac80c8c8d548c828: removed 12 log segments from log reader
I20260812 06:18:36.171146 24584 log.cc:1079] T 88484e6ebd7d4b43ac80c8c8d548c828 P 6d7f95c1981141c389bf9cd807d44979: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/88484e6ebd7d4b43ac80c8c8d548c828/wal-000000003 (ops 11-15)
I20260812 06:18:36.171196 24584 log.cc:1079] T 88484e6ebd7d4b43ac80c8c8d548c828 P 6d7f95c1981141c389bf9cd807d44979: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/88484e6ebd7d4b43ac80c8c8d548c828/wal-000000004 (ops 16-20)
I20260812 06:18:36.171231 24584 log.cc:1079] T 88484e6ebd7d4b43ac80c8c8d548c828 P 6d7f95c1981141c389bf9cd807d44979: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/88484e6ebd7d4b43ac80c8c8d548c828/wal-000000005 (ops 21-25)
I20260812 06:18:36.171254 24584 log.cc:1079] T 88484e6ebd7d4b43ac80c8c8d548c828 P 6d7f95c1981141c389bf9cd807d44979: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/88484e6ebd7d4b43ac80c8c8d548c828/wal-000000006 (ops 26-30)
I20260812 06:18:36.171284 24584 log.cc:1079] T 88484e6ebd7d4b43ac80c8c8d548c828 P 6d7f95c1981141c389bf9cd807d44979: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/88484e6ebd7d4b43ac80c8c8d548c828/wal-000000007 (ops 31-35)
I20260812 06:18:36.171315 24584 log.cc:1079] T 88484e6ebd7d4b43ac80c8c8d548c828 P 6d7f95c1981141c389bf9cd807d44979: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/88484e6ebd7d4b43ac80c8c8d548c828/wal-000000008 (ops 36-40)
I20260812 06:18:36.171346 24584 log.cc:1079] T 88484e6ebd7d4b43ac80c8c8d548c828 P 6d7f95c1981141c389bf9cd807d44979: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/88484e6ebd7d4b43ac80c8c8d548c828/wal-000000009 (ops 41-45)
I20260812 06:18:36.171377 24584 log.cc:1079] T 88484e6ebd7d4b43ac80c8c8d548c828 P 6d7f95c1981141c389bf9cd807d44979: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/88484e6ebd7d4b43ac80c8c8d548c828/wal-000000010 (ops 46-50)
I20260812 06:18:36.171408 24584 log.cc:1079] T 88484e6ebd7d4b43ac80c8c8d548c828 P 6d7f95c1981141c389bf9cd807d44979: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/88484e6ebd7d4b43ac80c8c8d548c828/wal-000000011 (ops 51-54)
I20260812 06:18:36.171438 24584 log.cc:1079] T 88484e6ebd7d4b43ac80c8c8d548c828 P 6d7f95c1981141c389bf9cd807d44979: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/88484e6ebd7d4b43ac80c8c8d548c828/wal-000000012 (ops 55-59)
I20260812 06:18:36.171468 24584 log.cc:1079] T 88484e6ebd7d4b43ac80c8c8d548c828 P 6d7f95c1981141c389bf9cd807d44979: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/88484e6ebd7d4b43ac80c8c8d548c828/wal-000000013 (ops 60-64)
I20260812 06:18:36.171497 24584 log.cc:1079] T 88484e6ebd7d4b43ac80c8c8d548c828 P 6d7f95c1981141c389bf9cd807d44979: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/88484e6ebd7d4b43ac80c8c8d548c828/wal-000000014 (ops 65-69)
I20260812 06:18:36.193584 24584 maintenance_manager.cc:643] P 6d7f95c1981141c389bf9cd807d44979: LogGCOp(88484e6ebd7d4b43ac80c8c8d548c828) complete. Timing: real 0.023s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:18:36.193974 24684 maintenance_manager.cc:419] P 6d7f95c1981141c389bf9cd807d44979: Scheduling UndoDeltaBlockGCOp(88484e6ebd7d4b43ac80c8c8d548c828): 471 bytes on disk
I20260812 06:18:36.194430 24584 maintenance_manager.cc:643] P 6d7f95c1981141c389bf9cd807d44979: UndoDeltaBlockGCOp(88484e6ebd7d4b43ac80c8c8d548c828) 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:18:36.194932 24684 maintenance_manager.cc:419] P 6d7f95c1981141c389bf9cd807d44979: Scheduling FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828): perf score=6.157687
I20260812 06:18:36.230415 24584 maintenance_manager.cc:643] P 6d7f95c1981141c389bf9cd807d44979: FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828) complete. Timing: real 0.035s	user 0.008s	sys 0.013s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":9481,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:18:36.230895 24684 maintenance_manager.cc:419] P 6d7f95c1981141c389bf9cd807d44979: Scheduling FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828): perf score=2.188937
I20260812 06:18:36.240967 24584 maintenance_manager.cc:643] P 6d7f95c1981141c389bf9cd807d44979: FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3686,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:36.241454 24684 maintenance_manager.cc:419] P 6d7f95c1981141c389bf9cd807d44979: Scheduling MajorDeltaCompactionOp(88484e6ebd7d4b43ac80c8c8d548c828): perf score=1.000000
I20260812 06:18:36.496904 24584 maintenance_manager.cc:643] P 6d7f95c1981141c389bf9cd807d44979: MajorDeltaCompactionOp(88484e6ebd7d4b43ac80c8c8d548c828) complete. Timing: real 0.255s	user 0.139s	sys 0.103s Metrics: {"cfile_cache_miss":834,"cfile_cache_miss_bytes":37123157,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":161,"lbm_read_time_us":16939,"lbm_reads_lt_1ms":874,"lbm_write_time_us":41083,"lbm_writes_lt_1ms":843,"mutex_wait_us":22,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":11776,"thread_start_us":98,"threads_started":1,"update_count":4000}
I20260812 06:18:36.497462 24684 maintenance_manager.cc:419] P 6d7f95c1981141c389bf9cd807d44979: Scheduling FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828): perf score=18.063937
I20260812 06:18:36.564313 24584 maintenance_manager.cc:643] P 6d7f95c1981141c389bf9cd807d44979: FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828) complete. Timing: real 0.067s	user 0.034s	sys 0.025s Metrics: {"bytes_written":20512314,"delete_count":0,"lbm_write_time_us":26273,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:36.564723 24684 maintenance_manager.cc:419] P 6d7f95c1981141c389bf9cd807d44979: Scheduling FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828): perf score=2.188937
I20260812 06:18:36.580264 24584 maintenance_manager.cc:643] P 6d7f95c1981141c389bf9cd807d44979: FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828) complete. Timing: real 0.015s	user 0.014s	sys 0.000s 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:36.580670 24684 maintenance_manager.cc:419] P 6d7f95c1981141c389bf9cd807d44979: Scheduling MajorDeltaCompactionOp(88484e6ebd7d4b43ac80c8c8d548c828): perf score=1.000000
I20260812 06:18:36.748762 24584 maintenance_manager.cc:643] P 6d7f95c1981141c389bf9cd807d44979: MajorDeltaCompactionOp(88484e6ebd7d4b43ac80c8c8d548c828) complete. Timing: real 0.168s	user 0.139s	sys 0.027s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918096,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":443,"lbm_read_time_us":9955,"lbm_reads_lt_1ms":668,"lbm_write_time_us":33561,"lbm_writes_lt_1ms":643,"mutex_wait_us":38,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":5248,"update_count":3000}
I20260812 06:18:36.749274 24684 maintenance_manager.cc:419] P 6d7f95c1981141c389bf9cd807d44979: Scheduling FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828): perf score=14.095187
I20260812 06:18:36.796511 24584 maintenance_manager.cc:643] P 6d7f95c1981141c389bf9cd807d44979: FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828) complete. Timing: real 0.047s	user 0.023s	sys 0.020s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19073,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:36.797029 24684 maintenance_manager.cc:419] P 6d7f95c1981141c389bf9cd807d44979: Scheduling FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828): perf score=2.188937
I20260812 06:18:36.806954 24584 maintenance_manager.cc:643] P 6d7f95c1981141c389bf9cd807d44979: FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3683,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:36.807499 24684 maintenance_manager.cc:419] P 6d7f95c1981141c389bf9cd807d44979: Scheduling MajorDeltaCompactionOp(88484e6ebd7d4b43ac80c8c8d548c828): perf score=1.000000
I20260812 06:18:36.968928 24584 maintenance_manager.cc:643] P 6d7f95c1981141c389bf9cd807d44979: MajorDeltaCompactionOp(88484e6ebd7d4b43ac80c8c8d548c828) complete. Timing: real 0.161s	user 0.116s	sys 0.029s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":682,"lbm_read_time_us":9813,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28476,"lbm_writes_lt_1ms":543,"mutex_wait_us":327,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3200,"update_count":2500}
I20260812 06:18:36.969501 24684 maintenance_manager.cc:419] P 6d7f95c1981141c389bf9cd807d44979: Scheduling FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828): perf score=14.095187
I20260812 06:18:37.021977 24584 maintenance_manager.cc:643] P 6d7f95c1981141c389bf9cd807d44979: FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828) complete. Timing: real 0.052s	user 0.033s	sys 0.003s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":17378,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:37.022532 24684 maintenance_manager.cc:419] P 6d7f95c1981141c389bf9cd807d44979: Scheduling FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828): perf score=2.188937
I20260812 06:18:37.035470 24584 maintenance_manager.cc:643] P 6d7f95c1981141c389bf9cd807d44979: FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828) complete. Timing: real 0.013s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4627,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:37.036159 24684 maintenance_manager.cc:419] P 6d7f95c1981141c389bf9cd807d44979: Scheduling MajorDeltaCompactionOp(88484e6ebd7d4b43ac80c8c8d548c828): perf score=1.000000
I20260812 06:18:37.212916 24584 maintenance_manager.cc:643] P 6d7f95c1981141c389bf9cd807d44979: MajorDeltaCompactionOp(88484e6ebd7d4b43ac80c8c8d548c828) complete. Timing: real 0.177s	user 0.123s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":193,"lbm_read_time_us":11681,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27518,"lbm_writes_lt_1ms":543,"mutex_wait_us":40,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4352,"update_count":2500}
I20260812 06:18:37.213460 24684 maintenance_manager.cc:419] P 6d7f95c1981141c389bf9cd807d44979: Scheduling FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828): perf score=14.095187
I20260812 06:18:37.251929 24584 maintenance_manager.cc:643] P 6d7f95c1981141c389bf9cd807d44979: FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828) complete. Timing: real 0.038s	user 0.018s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":16992,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:37.252399 24684 maintenance_manager.cc:419] P 6d7f95c1981141c389bf9cd807d44979: Scheduling MajorDeltaCompactionOp(88484e6ebd7d4b43ac80c8c8d548c828): perf score=1.000000
I20260812 06:18:37.394693 24584 maintenance_manager.cc:643] P 6d7f95c1981141c389bf9cd807d44979: MajorDeltaCompactionOp(88484e6ebd7d4b43ac80c8c8d548c828) complete. Timing: real 0.142s	user 0.091s	sys 0.049s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713152,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":515,"lbm_read_time_us":9264,"lbm_reads_lt_1ms":467,"lbm_write_time_us":23702,"lbm_writes_lt_1ms":443,"mutex_wait_us":263,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8192,"update_count":2000}
I20260812 06:18:37.395377 24684 maintenance_manager.cc:419] P 6d7f95c1981141c389bf9cd807d44979: Scheduling FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828): perf score=11.118625
I20260812 06:18:37.436929 24584 maintenance_manager.cc:643] P 6d7f95c1981141c389bf9cd807d44979: FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828) complete. Timing: real 0.041s	user 0.024s	sys 0.015s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":17842,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:37.437518 24684 maintenance_manager.cc:419] P 6d7f95c1981141c389bf9cd807d44979: Scheduling FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828): perf score=2.188937
I20260812 06:18:37.456676 24584 maintenance_manager.cc:643] P 6d7f95c1981141c389bf9cd807d44979: FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828) complete. Timing: real 0.019s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5282,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:37.457141 24684 maintenance_manager.cc:419] P 6d7f95c1981141c389bf9cd807d44979: Scheduling FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828): perf score=2.188937
I20260812 06:18:37.466905 24584 maintenance_manager.cc:643] P 6d7f95c1981141c389bf9cd807d44979: FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828) complete. Timing: real 0.010s	user 0.005s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3671,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:37.467478 24684 maintenance_manager.cc:419] P 6d7f95c1981141c389bf9cd807d44979: Scheduling MajorDeltaCompactionOp(88484e6ebd7d4b43ac80c8c8d548c828): perf score=1.000000
I20260812 06:18:37.649091 24584 maintenance_manager.cc:643] P 6d7f95c1981141c389bf9cd807d44979: MajorDeltaCompactionOp(88484e6ebd7d4b43ac80c8c8d548c828) complete. Timing: real 0.181s	user 0.126s	sys 0.052s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815793,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":202,"lbm_read_time_us":11490,"lbm_reads_lt_1ms":573,"lbm_write_time_us":27258,"lbm_writes_lt_1ms":543,"mutex_wait_us":18,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4480,"update_count":2500}
I20260812 06:18:37.649735 24684 maintenance_manager.cc:419] P 6d7f95c1981141c389bf9cd807d44979: Scheduling FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828): perf score=14.095187
I20260812 06:18:37.699290 24584 maintenance_manager.cc:643] P 6d7f95c1981141c389bf9cd807d44979: FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828) complete. Timing: real 0.049s	user 0.026s	sys 0.015s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19151,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:37.699847 24684 maintenance_manager.cc:419] P 6d7f95c1981141c389bf9cd807d44979: Scheduling FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828): perf score=2.188937
I20260812 06:18:37.710444 24584 maintenance_manager.cc:643] P 6d7f95c1981141c389bf9cd807d44979: FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3710,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:37.711082 24684 maintenance_manager.cc:419] P 6d7f95c1981141c389bf9cd807d44979: Scheduling FlushMRSOp(88484e6ebd7d4b43ac80c8c8d548c828): perf score=1.000000
I20260812 06:18:37.740377 24584 maintenance_manager.cc:643] P 6d7f95c1981141c389bf9cd807d44979: FlushMRSOp(88484e6ebd7d4b43ac80c8c8d548c828) complete. Timing: real 0.029s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":37,"dirs.run_cpu_time_us":163,"dirs.run_wall_time_us":1087,"drs_written":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1938,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:18:37.741039 24684 maintenance_manager.cc:419] P 6d7f95c1981141c389bf9cd807d44979: Scheduling LogGCOp(88484e6ebd7d4b43ac80c8c8d548c828): free 133024386 bytes of WAL
I20260812 06:18:37.741269 24584 log_reader.cc:385] T 88484e6ebd7d4b43ac80c8c8d548c828: removed 13 log segments from log reader
I20260812 06:18:37.741329 24584 log.cc:1079] T 88484e6ebd7d4b43ac80c8c8d548c828 P 6d7f95c1981141c389bf9cd807d44979: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/88484e6ebd7d4b43ac80c8c8d548c828/wal-000000015 (ops 70-74)
I20260812 06:18:37.741377 24584 log.cc:1079] T 88484e6ebd7d4b43ac80c8c8d548c828 P 6d7f95c1981141c389bf9cd807d44979: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/88484e6ebd7d4b43ac80c8c8d548c828/wal-000000016 (ops 75-78)
I20260812 06:18:37.741410 24584 log.cc:1079] T 88484e6ebd7d4b43ac80c8c8d548c828 P 6d7f95c1981141c389bf9cd807d44979: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/88484e6ebd7d4b43ac80c8c8d548c828/wal-000000017 (ops 79-83)
I20260812 06:18:37.741441 24584 log.cc:1079] T 88484e6ebd7d4b43ac80c8c8d548c828 P 6d7f95c1981141c389bf9cd807d44979: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/88484e6ebd7d4b43ac80c8c8d548c828/wal-000000018 (ops 84-88)
I20260812 06:18:37.741468 24584 log.cc:1079] T 88484e6ebd7d4b43ac80c8c8d548c828 P 6d7f95c1981141c389bf9cd807d44979: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/88484e6ebd7d4b43ac80c8c8d548c828/wal-000000019 (ops 89-93)
I20260812 06:18:37.741497 24584 log.cc:1079] T 88484e6ebd7d4b43ac80c8c8d548c828 P 6d7f95c1981141c389bf9cd807d44979: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/88484e6ebd7d4b43ac80c8c8d548c828/wal-000000020 (ops 94-98)
I20260812 06:18:37.741529 24584 log.cc:1079] T 88484e6ebd7d4b43ac80c8c8d548c828 P 6d7f95c1981141c389bf9cd807d44979: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/88484e6ebd7d4b43ac80c8c8d548c828/wal-000000021 (ops 99-103)
I20260812 06:18:37.741557 24584 log.cc:1079] T 88484e6ebd7d4b43ac80c8c8d548c828 P 6d7f95c1981141c389bf9cd807d44979: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/88484e6ebd7d4b43ac80c8c8d548c828/wal-000000022 (ops 104-108)
I20260812 06:18:37.741585 24584 log.cc:1079] T 88484e6ebd7d4b43ac80c8c8d548c828 P 6d7f95c1981141c389bf9cd807d44979: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/88484e6ebd7d4b43ac80c8c8d548c828/wal-000000023 (ops 109-113)
I20260812 06:18:37.741613 24584 log.cc:1079] T 88484e6ebd7d4b43ac80c8c8d548c828 P 6d7f95c1981141c389bf9cd807d44979: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/88484e6ebd7d4b43ac80c8c8d548c828/wal-000000024 (ops 114-118)
I20260812 06:18:37.741641 24584 log.cc:1079] T 88484e6ebd7d4b43ac80c8c8d548c828 P 6d7f95c1981141c389bf9cd807d44979: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/88484e6ebd7d4b43ac80c8c8d548c828/wal-000000025 (ops 119-123)
I20260812 06:18:37.741674 24584 log.cc:1079] T 88484e6ebd7d4b43ac80c8c8d548c828 P 6d7f95c1981141c389bf9cd807d44979: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/88484e6ebd7d4b43ac80c8c8d548c828/wal-000000026 (ops 124-128)
I20260812 06:18:37.741703 24584 log.cc:1079] T 88484e6ebd7d4b43ac80c8c8d548c828 P 6d7f95c1981141c389bf9cd807d44979: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/88484e6ebd7d4b43ac80c8c8d548c828/wal-000000027 (ops 129-133)
I20260812 06:18:37.768111 24584 maintenance_manager.cc:643] P 6d7f95c1981141c389bf9cd807d44979: LogGCOp(88484e6ebd7d4b43ac80c8c8d548c828) complete. Timing: real 0.027s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:18:37.768522 24684 maintenance_manager.cc:419] P 6d7f95c1981141c389bf9cd807d44979: Scheduling UndoDeltaBlockGCOp(88484e6ebd7d4b43ac80c8c8d548c828): 493 bytes on disk
I20260812 06:18:37.769094 24584 maintenance_manager.cc:643] P 6d7f95c1981141c389bf9cd807d44979: UndoDeltaBlockGCOp(88484e6ebd7d4b43ac80c8c8d548c828) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4}
I20260812 06:18:37.769696 24684 maintenance_manager.cc:419] P 6d7f95c1981141c389bf9cd807d44979: Scheduling FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828): perf score=3.181125
I20260812 06:18:37.794014 24584 maintenance_manager.cc:643] P 6d7f95c1981141c389bf9cd807d44979: FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828) complete. Timing: real 0.024s	user 0.010s	sys 0.001s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4930,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:37.794467 24684 maintenance_manager.cc:419] P 6d7f95c1981141c389bf9cd807d44979: Scheduling FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828): perf score=2.188937
I20260812 06:18:37.807794 24584 maintenance_manager.cc:643] P 6d7f95c1981141c389bf9cd807d44979: FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828) complete. Timing: real 0.013s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4836,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:37.808224 24684 maintenance_manager.cc:419] P 6d7f95c1981141c389bf9cd807d44979: Scheduling MajorDeltaCompactionOp(88484e6ebd7d4b43ac80c8c8d548c828): perf score=1.000000
I20260812 06:18:38.035842 24584 maintenance_manager.cc:643] P 6d7f95c1981141c389bf9cd807d44979: MajorDeltaCompactionOp(88484e6ebd7d4b43ac80c8c8d548c828) complete. Timing: real 0.227s	user 0.116s	sys 0.104s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020736,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":915,"lbm_read_time_us":15966,"lbm_reads_lt_1ms":774,"lbm_write_time_us":33156,"lbm_writes_lt_1ms":743,"mutex_wait_us":38,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":10112,"thread_start_us":88,"threads_started":1,"update_count":3500}
I20260812 06:18:38.036456 24684 maintenance_manager.cc:419] P 6d7f95c1981141c389bf9cd807d44979: Scheduling FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828): perf score=18.063937
I20260812 06:18:38.093339 24584 maintenance_manager.cc:643] P 6d7f95c1981141c389bf9cd807d44979: FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828) complete. Timing: real 0.057s	user 0.035s	sys 0.015s Metrics: {"bytes_written":20512311,"delete_count":0,"lbm_write_time_us":23538,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:38.094025 24684 maintenance_manager.cc:419] P 6d7f95c1981141c389bf9cd807d44979: Scheduling MajorDeltaCompactionOp(88484e6ebd7d4b43ac80c8c8d548c828): perf score=1.000000
I20260812 06:18:38.256419 24584 maintenance_manager.cc:643] P 6d7f95c1981141c389bf9cd807d44979: MajorDeltaCompactionOp(88484e6ebd7d4b43ac80c8c8d548c828) complete. Timing: real 0.162s	user 0.098s	sys 0.064s Metrics: {"cfile_cache_miss":531,"cfile_cache_miss_bytes":24815562,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":218,"lbm_read_time_us":12451,"lbm_reads_lt_1ms":563,"lbm_write_time_us":25876,"lbm_writes_lt_1ms":543,"mutex_wait_us":38,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":17920,"update_count":2500}
I20260812 06:18:38.257125 24684 maintenance_manager.cc:419] P 6d7f95c1981141c389bf9cd807d44979: Scheduling FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828): perf score=14.095187
I20260812 06:18:38.308157 24584 maintenance_manager.cc:643] P 6d7f95c1981141c389bf9cd807d44979: FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828) complete. Timing: real 0.051s	user 0.035s	sys 0.015s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":17626,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:38.308759 24684 maintenance_manager.cc:419] P 6d7f95c1981141c389bf9cd807d44979: Scheduling FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828): perf score=2.188937
I20260812 06:18:38.318981 24584 maintenance_manager.cc:643] P 6d7f95c1981141c389bf9cd807d44979: FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3777,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:38.319450 24684 maintenance_manager.cc:419] P 6d7f95c1981141c389bf9cd807d44979: Scheduling MajorDeltaCompactionOp(88484e6ebd7d4b43ac80c8c8d548c828): perf score=1.000000
I20260812 06:18:38.494935 24584 maintenance_manager.cc:643] P 6d7f95c1981141c389bf9cd807d44979: MajorDeltaCompactionOp(88484e6ebd7d4b43ac80c8c8d548c828) complete. Timing: real 0.175s	user 0.104s	sys 0.068s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":156,"lbm_read_time_us":12827,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28087,"lbm_writes_lt_1ms":543,"mutex_wait_us":19,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9344,"update_count":2500}
I20260812 06:18:38.495499 24684 maintenance_manager.cc:419] P 6d7f95c1981141c389bf9cd807d44979: Scheduling FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828): perf score=14.095187
I20260812 06:18:38.546748 24584 maintenance_manager.cc:643] P 6d7f95c1981141c389bf9cd807d44979: FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828) complete. Timing: real 0.051s	user 0.036s	sys 0.010s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":17491,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:38.547256 24684 maintenance_manager.cc:419] P 6d7f95c1981141c389bf9cd807d44979: Scheduling FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828): perf score=2.188937
I20260812 06:18:38.557358 24584 maintenance_manager.cc:643] P 6d7f95c1981141c389bf9cd807d44979: FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3768,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:38.557775 24684 maintenance_manager.cc:419] P 6d7f95c1981141c389bf9cd807d44979: Scheduling MajorDeltaCompactionOp(88484e6ebd7d4b43ac80c8c8d548c828): perf score=1.000000
I20260812 06:18:38.737922 24584 maintenance_manager.cc:643] P 6d7f95c1981141c389bf9cd807d44979: MajorDeltaCompactionOp(88484e6ebd7d4b43ac80c8c8d548c828) complete. Timing: real 0.180s	user 0.119s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":528,"lbm_read_time_us":13831,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27155,"lbm_writes_lt_1ms":543,"mutex_wait_us":255,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5888,"update_count":2500}
I20260812 06:18:38.738477 24684 maintenance_manager.cc:419] P 6d7f95c1981141c389bf9cd807d44979: Scheduling FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828): perf score=14.095187
I20260812 06:18:38.783356 24584 maintenance_manager.cc:643] P 6d7f95c1981141c389bf9cd807d44979: FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828) complete. Timing: real 0.045s	user 0.029s	sys 0.008s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":17602,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:38.783942 24684 maintenance_manager.cc:419] P 6d7f95c1981141c389bf9cd807d44979: Scheduling FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828): perf score=2.188937
I20260812 06:18:38.794142 24584 maintenance_manager.cc:643] P 6d7f95c1981141c389bf9cd807d44979: FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3634,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:38.794866 24684 maintenance_manager.cc:419] P 6d7f95c1981141c389bf9cd807d44979: Scheduling MajorDeltaCompactionOp(88484e6ebd7d4b43ac80c8c8d548c828): perf score=1.000000
I20260812 06:18:38.979044 24584 maintenance_manager.cc:643] P 6d7f95c1981141c389bf9cd807d44979: MajorDeltaCompactionOp(88484e6ebd7d4b43ac80c8c8d548c828) complete. Timing: real 0.184s	user 0.117s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":127,"lbm_read_time_us":11205,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28749,"lbm_writes_lt_1ms":543,"mutex_wait_us":18,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":17536,"update_count":2500}
I20260812 06:18:38.979606 24684 maintenance_manager.cc:419] P 6d7f95c1981141c389bf9cd807d44979: Scheduling FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828): perf score=14.095187
I20260812 06:18:39.019586 24584 maintenance_manager.cc:643] P 6d7f95c1981141c389bf9cd807d44979: FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828) complete. Timing: real 0.040s	user 0.026s	sys 0.009s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":16845,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:39.020174 24684 maintenance_manager.cc:419] P 6d7f95c1981141c389bf9cd807d44979: Scheduling FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828): perf score=2.188937
I20260812 06:18:39.035302 24584 maintenance_manager.cc:643] P 6d7f95c1981141c389bf9cd807d44979: FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5566,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:39.035873 24684 maintenance_manager.cc:419] P 6d7f95c1981141c389bf9cd807d44979: Scheduling MajorDeltaCompactionOp(88484e6ebd7d4b43ac80c8c8d548c828): perf score=1.000000
I20260812 06:18:39.199323 24584 maintenance_manager.cc:643] P 6d7f95c1981141c389bf9cd807d44979: MajorDeltaCompactionOp(88484e6ebd7d4b43ac80c8c8d548c828) complete. Timing: real 0.163s	user 0.119s	sys 0.028s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":598,"dirs.run_cpu_time_us":364,"dirs.run_wall_time_us":2905,"lbm_read_time_us":9409,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28528,"lbm_writes_lt_1ms":543,"mutex_wait_us":27,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":2500}
I20260812 06:18:39.199982 24684 maintenance_manager.cc:419] P 6d7f95c1981141c389bf9cd807d44979: Scheduling FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828): perf score=14.095187
I20260812 06:18:39.240376 24584 maintenance_manager.cc:643] P 6d7f95c1981141c389bf9cd807d44979: FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828) complete. Timing: real 0.040s	user 0.026s	sys 0.013s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":17400,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:39.240976 24684 maintenance_manager.cc:419] P 6d7f95c1981141c389bf9cd807d44979: Scheduling FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828): perf score=2.188937
I20260812 06:18:39.250970 24584 maintenance_manager.cc:643] P 6d7f95c1981141c389bf9cd807d44979: FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3815,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:39.251436 24684 maintenance_manager.cc:419] P 6d7f95c1981141c389bf9cd807d44979: Scheduling FlushMRSOp(88484e6ebd7d4b43ac80c8c8d548c828): perf score=1.000000
I20260812 06:18:39.283092 24067 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.674s	user 1.741s	sys 0.149s
I20260812 06:18:39.285593 24584 maintenance_manager.cc:643] P 6d7f95c1981141c389bf9cd807d44979: FlushMRSOp(88484e6ebd7d4b43ac80c8c8d548c828) complete. Timing: real 0.034s	user 0.022s	sys 0.007s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":61,"dirs.run_cpu_time_us":183,"dirs.run_wall_time_us":1185,"drs_written":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2151,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:18:39.286350 24684 maintenance_manager.cc:419] P 6d7f95c1981141c389bf9cd807d44979: Scheduling LogGCOp(88484e6ebd7d4b43ac80c8c8d548c828): free 136728516 bytes of WAL
I20260812 06:18:39.286616 24584 log_reader.cc:385] T 88484e6ebd7d4b43ac80c8c8d548c828: removed 13 log segments from log reader
I20260812 06:18:39.286706 24584 log.cc:1079] T 88484e6ebd7d4b43ac80c8c8d548c828 P 6d7f95c1981141c389bf9cd807d44979: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/88484e6ebd7d4b43ac80c8c8d548c828/wal-000000028 (ops 134-138)
I20260812 06:18:39.286772 24584 log.cc:1079] T 88484e6ebd7d4b43ac80c8c8d548c828 P 6d7f95c1981141c389bf9cd807d44979: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/88484e6ebd7d4b43ac80c8c8d548c828/wal-000000029 (ops 139-143)
I20260812 06:18:39.286829 24584 log.cc:1079] T 88484e6ebd7d4b43ac80c8c8d548c828 P 6d7f95c1981141c389bf9cd807d44979: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/88484e6ebd7d4b43ac80c8c8d548c828/wal-000000030 (ops 144-148)
I20260812 06:18:39.286901 24584 log.cc:1079] T 88484e6ebd7d4b43ac80c8c8d548c828 P 6d7f95c1981141c389bf9cd807d44979: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/88484e6ebd7d4b43ac80c8c8d548c828/wal-000000031 (ops 149-153)
I20260812 06:18:39.286957 24584 log.cc:1079] T 88484e6ebd7d4b43ac80c8c8d548c828 P 6d7f95c1981141c389bf9cd807d44979: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/88484e6ebd7d4b43ac80c8c8d548c828/wal-000000032 (ops 154-158)
I20260812 06:18:39.286983 24584 log.cc:1079] T 88484e6ebd7d4b43ac80c8c8d548c828 P 6d7f95c1981141c389bf9cd807d44979: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/88484e6ebd7d4b43ac80c8c8d548c828/wal-000000033 (ops 159-163)
I20260812 06:18:39.287037 24584 log.cc:1079] T 88484e6ebd7d4b43ac80c8c8d548c828 P 6d7f95c1981141c389bf9cd807d44979: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/88484e6ebd7d4b43ac80c8c8d548c828/wal-000000034 (ops 164-168)
I20260812 06:18:39.287076 24584 log.cc:1079] T 88484e6ebd7d4b43ac80c8c8d548c828 P 6d7f95c1981141c389bf9cd807d44979: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/88484e6ebd7d4b43ac80c8c8d548c828/wal-000000035 (ops 169-173)
I20260812 06:18:39.287102 24584 log.cc:1079] T 88484e6ebd7d4b43ac80c8c8d548c828 P 6d7f95c1981141c389bf9cd807d44979: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/88484e6ebd7d4b43ac80c8c8d548c828/wal-000000036 (ops 174-178)
I20260812 06:18:39.287132 24584 log.cc:1079] T 88484e6ebd7d4b43ac80c8c8d548c828 P 6d7f95c1981141c389bf9cd807d44979: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/88484e6ebd7d4b43ac80c8c8d548c828/wal-000000037 (ops 179-183)
I20260812 06:18:39.287158 24584 log.cc:1079] T 88484e6ebd7d4b43ac80c8c8d548c828 P 6d7f95c1981141c389bf9cd807d44979: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/88484e6ebd7d4b43ac80c8c8d548c828/wal-000000038 (ops 184-188)
I20260812 06:18:39.287191 24584 log.cc:1079] T 88484e6ebd7d4b43ac80c8c8d548c828 P 6d7f95c1981141c389bf9cd807d44979: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/88484e6ebd7d4b43ac80c8c8d548c828/wal-000000039 (ops 189-193)
I20260812 06:18:39.287220 24584 log.cc:1079] T 88484e6ebd7d4b43ac80c8c8d548c828 P 6d7f95c1981141c389bf9cd807d44979: Deleting log segment in path: /tmp/dist-test-taskMtI4uS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515509348364-24067-0/minicluster-data/ts-0-root/wals/88484e6ebd7d4b43ac80c8c8d548c828/wal-000000040 (ops 194-198)
I20260812 06:18:39.318157 24584 maintenance_manager.cc:643] P 6d7f95c1981141c389bf9cd807d44979: LogGCOp(88484e6ebd7d4b43ac80c8c8d548c828) complete. Timing: real 0.032s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:18:39.318624 24684 maintenance_manager.cc:419] P 6d7f95c1981141c389bf9cd807d44979: Scheduling FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828): perf score=2.188937
I20260812 06:18:39.327991 24584 maintenance_manager.cc:643] P 6d7f95c1981141c389bf9cd807d44979: FlushDeltaMemStoresOp(88484e6ebd7d4b43ac80c8c8d548c828) complete. Timing: real 0.009s	user 0.003s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3612,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:39.328577 24684 maintenance_manager.cc:419] P 6d7f95c1981141c389bf9cd807d44979: Scheduling MajorDeltaCompactionOp(88484e6ebd7d4b43ac80c8c8d548c828): perf score=1.000000
I20260812 06:18:39.339313 24067 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.056s	user 0.001s	sys 0.000s
I20260812 06:18:39.339824 24067 tablet_server.cc:179] TabletServer@127.23.128.193:0 shutting down...
I20260812 06:18:39.445976 24584 maintenance_manager.cc:643] P 6d7f95c1981141c389bf9cd807d44979: MajorDeltaCompactionOp(88484e6ebd7d4b43ac80c8c8d548c828) complete. Timing: real 0.117s	user 0.095s	sys 0.022s Metrics: {"cfile_cache_hit":532,"cfile_cache_hit_bytes":24815684,"cfile_cache_miss":101,"cfile_cache_miss_bytes":4102531,"cfile_init":3,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":479,"lbm_read_time_us":1740,"lbm_reads_lt_1ms":113,"lbm_write_time_us":25943,"lbm_writes_lt_1ms":643,"mutex_wait_us":62,"peak_mem_usage":75542472,"reinsert_count":0,"thread_start_us":83,"threads_started":1,"update_count":3000}
I20260812 06:18:39.447400 24067 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:39.447635 24067 tablet_replica.cc:333] T 88484e6ebd7d4b43ac80c8c8d548c828 P 6d7f95c1981141c389bf9cd807d44979: stopping tablet replica
I20260812 06:18:39.447795 24067 raft_consensus.cc:2243] T 88484e6ebd7d4b43ac80c8c8d548c828 P 6d7f95c1981141c389bf9cd807d44979 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:39.447988 24067 raft_consensus.cc:2272] T 88484e6ebd7d4b43ac80c8c8d548c828 P 6d7f95c1981141c389bf9cd807d44979 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:39.462617 24067 tablet_server.cc:196] TabletServer@127.23.128.193:0 shutdown complete.
I20260812 06:18:39.496575 24067 master.cc:562] Master@127.23.128.254:37291 shutting down...
I20260812 06:18:39.499984 24067 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 63f636c9452e49ea8411d504257d7673 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:39.500159 24067 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 63f636c9452e49ea8411d504257d7673 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:39.500222 24067 tablet_replica.cc:333] T 00000000000000000000000000000000 P 63f636c9452e49ea8411d504257d7673: stopping tablet replica
I20260812 06:18:39.512267 24067 master.cc:584] Master@127.23.128.254:37291 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5151 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10226 ms total)

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