[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:19:31.808436 16945 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.16.140.126:39871
I20260812 06:19:31.809406 16945 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:19:31.809994 16945 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:31.815801 16953 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:31.815981 16954 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:31.815884 16945 server_base.cc:1061] running on GCE node
W20260812 06:19:31.816107 16958 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:31.816606 16945 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:31.816699 16945 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:31.816741 16945 hybrid_clock.cc:648] HybridClock initialized: now 1786515571816738 us; error 0 us; skew 500 ppm
I20260812 06:19:31.818341 16945 webserver.cc:533] Webserver started at http://127.16.140.126:38589/ using document root <none> and password file <none>
I20260812 06:19:31.818898 16945 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:31.818964 16945 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:31.819190 16945 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:31.820734 16945 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515571797997-16945-0/minicluster-data/master-0-root/instance:
uuid: "287f51b0a2f444238a1169eaa44f974f"
format_stamp: "Formatted at 2026-08-12 06:19:31 on dist-test-slave-5bn2"
I20260812 06:19:31.823982 16945 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.004s	sys 0.000s
I20260812 06:19:31.825918 16964 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:31.826872 16945 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.001s
I20260812 06:19:31.826980 16945 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515571797997-16945-0/minicluster-data/master-0-root
uuid: "287f51b0a2f444238a1169eaa44f974f"
format_stamp: "Formatted at 2026-08-12 06:19:31 on dist-test-slave-5bn2"
I20260812 06:19:31.827064 16945 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515571797997-16945-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515571797997-16945-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515571797997-16945-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:31.845360 16945 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:31.845932 16945 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:19:31.846091 16945 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:31.853729 17043 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.16.140.126:39871 every 8 connection(s)
I20260812 06:19:31.853730 16945 rpc_server.cc:307] RPC server started. Bound to: 127.16.140.126:39871
I20260812 06:19:31.855989 17044 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:31.861138 17044 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 287f51b0a2f444238a1169eaa44f974f: Bootstrap starting.
I20260812 06:19:31.863426 17044 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 287f51b0a2f444238a1169eaa44f974f: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:31.864269 17044 log.cc:826] T 00000000000000000000000000000000 P 287f51b0a2f444238a1169eaa44f974f: Log is configured to *not* fsync() on all Append() calls
I20260812 06:19:31.865775 17044 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 287f51b0a2f444238a1169eaa44f974f: No bootstrap required, opened a new log
I20260812 06:19:31.868472 17044 raft_consensus.cc:359] T 00000000000000000000000000000000 P 287f51b0a2f444238a1169eaa44f974f [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "287f51b0a2f444238a1169eaa44f974f" member_type: VOTER }
I20260812 06:19:31.868624 17044 raft_consensus.cc:385] T 00000000000000000000000000000000 P 287f51b0a2f444238a1169eaa44f974f [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:31.868690 17044 raft_consensus.cc:740] T 00000000000000000000000000000000 P 287f51b0a2f444238a1169eaa44f974f [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 287f51b0a2f444238a1169eaa44f974f, State: Initialized, Role: FOLLOWER
I20260812 06:19:31.869230 17044 consensus_queue.cc:260] T 00000000000000000000000000000000 P 287f51b0a2f444238a1169eaa44f974f [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: "287f51b0a2f444238a1169eaa44f974f" member_type: VOTER }
I20260812 06:19:31.869372 17044 raft_consensus.cc:399] T 00000000000000000000000000000000 P 287f51b0a2f444238a1169eaa44f974f [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:31.869441 17044 raft_consensus.cc:493] T 00000000000000000000000000000000 P 287f51b0a2f444238a1169eaa44f974f [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:31.869558 17044 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 287f51b0a2f444238a1169eaa44f974f [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:31.870278 17044 raft_consensus.cc:515] T 00000000000000000000000000000000 P 287f51b0a2f444238a1169eaa44f974f [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "287f51b0a2f444238a1169eaa44f974f" member_type: VOTER }
I20260812 06:19:31.870680 17044 leader_election.cc:304] T 00000000000000000000000000000000 P 287f51b0a2f444238a1169eaa44f974f [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: 287f51b0a2f444238a1169eaa44f974f; no voters: 
I20260812 06:19:31.870978 17044 leader_election.cc:290] T 00000000000000000000000000000000 P 287f51b0a2f444238a1169eaa44f974f [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:31.871068 17047 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 287f51b0a2f444238a1169eaa44f974f [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:31.871277 17047 raft_consensus.cc:697] T 00000000000000000000000000000000 P 287f51b0a2f444238a1169eaa44f974f [term 1 LEADER]: Becoming Leader. State: Replica: 287f51b0a2f444238a1169eaa44f974f, State: Running, Role: LEADER
I20260812 06:19:31.871651 17047 consensus_queue.cc:237] T 00000000000000000000000000000000 P 287f51b0a2f444238a1169eaa44f974f [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: "287f51b0a2f444238a1169eaa44f974f" member_type: VOTER }
I20260812 06:19:31.871858 17044 sys_catalog.cc:565] T 00000000000000000000000000000000 P 287f51b0a2f444238a1169eaa44f974f [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:31.873255 17050 sys_catalog.cc:455] T 00000000000000000000000000000000 P 287f51b0a2f444238a1169eaa44f974f [sys.catalog]: SysCatalogTable state changed. Reason: New leader 287f51b0a2f444238a1169eaa44f974f. Latest consensus state: current_term: 1 leader_uuid: "287f51b0a2f444238a1169eaa44f974f" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "287f51b0a2f444238a1169eaa44f974f" member_type: VOTER } }
I20260812 06:19:31.873301 17049 sys_catalog.cc:455] T 00000000000000000000000000000000 P 287f51b0a2f444238a1169eaa44f974f [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "287f51b0a2f444238a1169eaa44f974f" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "287f51b0a2f444238a1169eaa44f974f" member_type: VOTER } }
I20260812 06:19:31.873354 17050 sys_catalog.cc:458] T 00000000000000000000000000000000 P 287f51b0a2f444238a1169eaa44f974f [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:31.873411 17049 sys_catalog.cc:458] T 00000000000000000000000000000000 P 287f51b0a2f444238a1169eaa44f974f [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:31.873700 17071 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:31.873973 16945 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:31.876065 17071 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:31.883072 17071 catalog_manager.cc:1383] Generated new cluster ID: fc9eaf1797fa43dab44be07a3fd2e841
I20260812 06:19:31.883213 17071 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:31.896972 17071 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:31.897744 17071 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:31.902223 17071 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 287f51b0a2f444238a1169eaa44f974f: Generated new TSK 0
I20260812 06:19:31.902760 17071 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:31.906665 16945 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:31.909006 17088 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:31.909036 17084 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:31.909220 17085 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:31.909260 16945 server_base.cc:1061] running on GCE node
I20260812 06:19:31.909454 16945 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:31.909504 16945 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:31.909518 16945 hybrid_clock.cc:648] HybridClock initialized: now 1786515571909518 us; error 0 us; skew 500 ppm
I20260812 06:19:31.910334 16945 webserver.cc:533] Webserver started at http://127.16.140.65:42607/ using document root <none> and password file <none>
I20260812 06:19:31.910485 16945 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:31.910529 16945 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:31.910599 16945 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:31.910979 16945 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515571797997-16945-0/minicluster-data/ts-0-root/instance:
uuid: "4903f51b9dfc4f35aec8123e5f2034a0"
format_stamp: "Formatted at 2026-08-12 06:19:31 on dist-test-slave-5bn2"
I20260812 06:19:31.912335 16945 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:31.913272 17101 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:31.913533 16945 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:31.913599 16945 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515571797997-16945-0/minicluster-data/ts-0-root
uuid: "4903f51b9dfc4f35aec8123e5f2034a0"
format_stamp: "Formatted at 2026-08-12 06:19:31 on dist-test-slave-5bn2"
I20260812 06:19:31.913661 16945 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515571797997-16945-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515571797997-16945-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515571797997-16945-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:31.926592 16945 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:31.927378 16945 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:31.927819 16945 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:31.928615 16945 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:31.928666 16945 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:31.928722 16945 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:31.928750 16945 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:31.934773 16945 rpc_server.cc:307] RPC server started. Bound to: 127.16.140.65:40539
I20260812 06:19:31.934821 17198 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.16.140.65:40539 every 8 connection(s)
I20260812 06:19:31.946724 17199 heartbeater.cc:344] Connected to a master server at 127.16.140.126:39871
I20260812 06:19:31.946988 17199 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:31.947458 17199 heartbeater.cc:507] Master 127.16.140.126:39871 requested a full tablet report, sending...
I20260812 06:19:31.948844 16989 ts_manager.cc:194] Registered new tserver with Master: 4903f51b9dfc4f35aec8123e5f2034a0 (127.16.140.65:40539)
I20260812 06:19:31.948925 16945 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.013578596s
I20260812 06:19:31.950328 16989 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:38688
I20260812 06:19:31.958873 16989 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:38692:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:31.972630 17146 tablet_service.cc:1511] Processing CreateTablet for tablet 07096636bd644803bc3f44622a26f8a7 (DEFAULT_TABLE table=heavy-update-compaction-test [id=374755ca81c34c9c9d6b24c411b0bb41]), partition=
I20260812 06:19:31.973081 17146 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 07096636bd644803bc3f44622a26f8a7. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:31.975169 17217 tablet_bootstrap.cc:492] T 07096636bd644803bc3f44622a26f8a7 P 4903f51b9dfc4f35aec8123e5f2034a0: Bootstrap starting.
I20260812 06:19:31.976150 17217 tablet_bootstrap.cc:654] T 07096636bd644803bc3f44622a26f8a7 P 4903f51b9dfc4f35aec8123e5f2034a0: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:31.977062 17217 tablet_bootstrap.cc:492] T 07096636bd644803bc3f44622a26f8a7 P 4903f51b9dfc4f35aec8123e5f2034a0: No bootstrap required, opened a new log
I20260812 06:19:31.977144 17217 ts_tablet_manager.cc:1403] T 07096636bd644803bc3f44622a26f8a7 P 4903f51b9dfc4f35aec8123e5f2034a0: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:19:31.977526 17217 raft_consensus.cc:359] T 07096636bd644803bc3f44622a26f8a7 P 4903f51b9dfc4f35aec8123e5f2034a0 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4903f51b9dfc4f35aec8123e5f2034a0" member_type: VOTER last_known_addr { host: "127.16.140.65" port: 40539 } }
I20260812 06:19:31.977617 17217 raft_consensus.cc:385] T 07096636bd644803bc3f44622a26f8a7 P 4903f51b9dfc4f35aec8123e5f2034a0 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:31.977649 17217 raft_consensus.cc:740] T 07096636bd644803bc3f44622a26f8a7 P 4903f51b9dfc4f35aec8123e5f2034a0 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 4903f51b9dfc4f35aec8123e5f2034a0, State: Initialized, Role: FOLLOWER
I20260812 06:19:31.977771 17217 consensus_queue.cc:260] T 07096636bd644803bc3f44622a26f8a7 P 4903f51b9dfc4f35aec8123e5f2034a0 [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: "4903f51b9dfc4f35aec8123e5f2034a0" member_type: VOTER last_known_addr { host: "127.16.140.65" port: 40539 } }
I20260812 06:19:31.977844 17217 raft_consensus.cc:399] T 07096636bd644803bc3f44622a26f8a7 P 4903f51b9dfc4f35aec8123e5f2034a0 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:31.977882 17217 raft_consensus.cc:493] T 07096636bd644803bc3f44622a26f8a7 P 4903f51b9dfc4f35aec8123e5f2034a0 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:31.977931 17217 raft_consensus.cc:3060] T 07096636bd644803bc3f44622a26f8a7 P 4903f51b9dfc4f35aec8123e5f2034a0 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:31.978637 17217 raft_consensus.cc:515] T 07096636bd644803bc3f44622a26f8a7 P 4903f51b9dfc4f35aec8123e5f2034a0 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4903f51b9dfc4f35aec8123e5f2034a0" member_type: VOTER last_known_addr { host: "127.16.140.65" port: 40539 } }
I20260812 06:19:31.978775 17217 leader_election.cc:304] T 07096636bd644803bc3f44622a26f8a7 P 4903f51b9dfc4f35aec8123e5f2034a0 [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: 4903f51b9dfc4f35aec8123e5f2034a0; no voters: 
I20260812 06:19:31.978981 17217 leader_election.cc:290] T 07096636bd644803bc3f44622a26f8a7 P 4903f51b9dfc4f35aec8123e5f2034a0 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:31.979082 17219 raft_consensus.cc:2804] T 07096636bd644803bc3f44622a26f8a7 P 4903f51b9dfc4f35aec8123e5f2034a0 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:31.979275 17219 raft_consensus.cc:697] T 07096636bd644803bc3f44622a26f8a7 P 4903f51b9dfc4f35aec8123e5f2034a0 [term 1 LEADER]: Becoming Leader. State: Replica: 4903f51b9dfc4f35aec8123e5f2034a0, State: Running, Role: LEADER
I20260812 06:19:31.979310 17217 ts_tablet_manager.cc:1434] T 07096636bd644803bc3f44622a26f8a7 P 4903f51b9dfc4f35aec8123e5f2034a0: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:19:31.979414 17219 consensus_queue.cc:237] T 07096636bd644803bc3f44622a26f8a7 P 4903f51b9dfc4f35aec8123e5f2034a0 [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: "4903f51b9dfc4f35aec8123e5f2034a0" member_type: VOTER last_known_addr { host: "127.16.140.65" port: 40539 } }
I20260812 06:19:31.979717 17199 heartbeater.cc:499] Master 127.16.140.126:39871 was elected leader, sending a full tablet report...
I20260812 06:19:31.981979 16989 catalog_manager.cc:5719] T 07096636bd644803bc3f44622a26f8a7 P 4903f51b9dfc4f35aec8123e5f2034a0 reported cstate change: term changed from 0 to 1, leader changed from <none> to 4903f51b9dfc4f35aec8123e5f2034a0 (127.16.140.65). New cstate: current_term: 1 leader_uuid: "4903f51b9dfc4f35aec8123e5f2034a0" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4903f51b9dfc4f35aec8123e5f2034a0" member_type: VOTER last_known_addr { host: "127.16.140.65" port: 40539 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:32.049959 16945 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.061s	user 0.023s	sys 0.008s
I20260812 06:19:32.185883 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling FlushMRSOp(07096636bd644803bc3f44622a26f8a7): perf score=19.054940
I20260812 06:19:32.346413 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: FlushMRSOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.160s	user 0.135s	sys 0.016s Metrics: {"bytes_written":12307490,"cfile_init":1,"compiler_manager_pool.queue_time_us":207,"delete_count":0,"dirs.queue_time_us":34,"dirs.run_cpu_time_us":199,"dirs.run_wall_time_us":734,"drs_written":1,"lbm_read_time_us":69,"lbm_reads_lt_1ms":4,"lbm_write_time_us":39475,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":120,"threads_started":1,"update_count":1500}
I20260812 06:19:32.347494 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling LogGCOp(07096636bd644803bc3f44622a26f8a7): free 20743880 bytes of WAL
I20260812 06:19:32.347781 17106 log_reader.cc:385] T 07096636bd644803bc3f44622a26f8a7: removed 2 log segments from log reader
I20260812 06:19:32.347841 17106 log.cc:1079] T 07096636bd644803bc3f44622a26f8a7 P 4903f51b9dfc4f35aec8123e5f2034a0: Deleting log segment in path: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515571797997-16945-0/minicluster-data/ts-0-root/wals/07096636bd644803bc3f44622a26f8a7/wal-000000001 (ops 1-6)
I20260812 06:19:32.347893 17106 log.cc:1079] T 07096636bd644803bc3f44622a26f8a7 P 4903f51b9dfc4f35aec8123e5f2034a0: Deleting log segment in path: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515571797997-16945-0/minicluster-data/ts-0-root/wals/07096636bd644803bc3f44622a26f8a7/wal-000000002 (ops 7-11)
I20260812 06:19:32.351449 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: LogGCOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.004s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:19:32.351711 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling UndoDeltaBlockGCOp(07096636bd644803bc3f44622a26f8a7): 16411393 bytes on disk
I20260812 06:19:32.352188 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: UndoDeltaBlockGCOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4}
I20260812 06:19:32.352514 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7): perf score=2.188937
I20260812 06:19:32.365284 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.013s	user 0.008s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4485,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:32.365926 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling MajorDeltaCompactionOp(07096636bd644803bc3f44622a26f8a7): perf score=1.000000
I20260812 06:19:32.491671 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: MajorDeltaCompactionOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.126s	user 0.097s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":786,"lbm_read_time_us":6649,"lbm_reads_lt_1ms":460,"lbm_write_time_us":23262,"lbm_writes_lt_1ms":443,"mutex_wait_us":27,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5760,"thread_start_us":267,"threads_started":5,"update_count":2000}
I20260812 06:19:32.492125 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7): perf score=10.126437
I20260812 06:19:32.534628 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.042s	user 0.020s	sys 0.020s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18390,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:32.535176 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7): perf score=2.188937
I20260812 06:19:32.545814 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.010s	user 0.003s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3464,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:32.546346 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling MajorDeltaCompactionOp(07096636bd644803bc3f44622a26f8a7): perf score=1.000000
I20260812 06:19:32.673465 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: MajorDeltaCompactionOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.127s	user 0.106s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":119,"lbm_read_time_us":9549,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21812,"lbm_writes_lt_1ms":443,"mutex_wait_us":52,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:19:32.674048 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7): perf score=10.126437
I20260812 06:19:32.715530 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.041s	user 0.017s	sys 0.020s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17078,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:19:32.715982 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7): perf score=2.188937
I20260812 06:19:32.725750 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3617,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:32.726255 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling MajorDeltaCompactionOp(07096636bd644803bc3f44622a26f8a7): perf score=1.000000
I20260812 06:19:32.845137 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: MajorDeltaCompactionOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.117s	user 0.097s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":214,"lbm_read_time_us":9361,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21582,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":74752,"update_count":2000}
I20260812 06:19:32.845610 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7): perf score=10.126437
I20260812 06:19:32.888581 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.043s	user 0.018s	sys 0.018s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":14069,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:32.889057 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7): perf score=2.188937
I20260812 06:19:32.898933 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.010s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3678,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:32.899324 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling MajorDeltaCompactionOp(07096636bd644803bc3f44622a26f8a7): perf score=1.000000
I20260812 06:19:33.029670 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: MajorDeltaCompactionOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.130s	user 0.087s	sys 0.041s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":91,"lbm_read_time_us":9580,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21623,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":50432,"update_count":2000}
I20260812 06:19:33.030148 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7): perf score=10.126437
I20260812 06:19:33.074646 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.044s	user 0.014s	sys 0.016s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":14196,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:33.075103 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7): perf score=2.188937
I20260812 06:19:33.084836 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3519,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:33.085394 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling MajorDeltaCompactionOp(07096636bd644803bc3f44622a26f8a7): perf score=1.000000
I20260812 06:19:33.196331 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: MajorDeltaCompactionOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.111s	user 0.092s	sys 0.017s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672280,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":228,"lbm_read_time_us":6747,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22590,"lbm_writes_lt_1ms":443,"mutex_wait_us":2,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:33.196787 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7): perf score=10.126437
I20260812 06:19:33.240142 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.043s	user 0.035s	sys 0.001s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15868,"lbm_writes_lt_1ms":303,"mutex_wait_us":2,"reinsert_count":0,"update_count":1500}
I20260812 06:19:33.240626 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7): perf score=2.188937
I20260812 06:19:33.250326 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3571,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:33.250806 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling MajorDeltaCompactionOp(07096636bd644803bc3f44622a26f8a7): perf score=1.000000
I20260812 06:19:33.361280 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: MajorDeltaCompactionOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.110s	user 0.086s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":323,"lbm_read_time_us":6883,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21409,"lbm_writes_lt_1ms":443,"mutex_wait_us":72,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:19:33.361752 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7): perf score=10.126437
I20260812 06:19:33.407177 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.045s	user 0.025s	sys 0.011s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":12781,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:33.407727 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7): perf score=2.188937
I20260812 06:19:33.417783 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3798,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:33.418267 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling FlushMRSOp(07096636bd644803bc3f44622a26f8a7): perf score=1.000000
I20260812 06:19:33.458642 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: FlushMRSOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.040s	user 0.023s	sys 0.004s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":60,"dirs.run_cpu_time_us":229,"dirs.run_wall_time_us":1268,"drs_written":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1326,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:33.459606 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling LogGCOp(07096636bd644803bc3f44622a26f8a7): free 111786258 bytes of WAL
I20260812 06:19:33.459852 17106 log_reader.cc:385] T 07096636bd644803bc3f44622a26f8a7: removed 11 log segments from log reader
I20260812 06:19:33.459904 17106 log.cc:1079] T 07096636bd644803bc3f44622a26f8a7 P 4903f51b9dfc4f35aec8123e5f2034a0: Deleting log segment in path: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515571797997-16945-0/minicluster-data/ts-0-root/wals/07096636bd644803bc3f44622a26f8a7/wal-000000003 (ops 12-16)
I20260812 06:19:33.459942 17106 log.cc:1079] T 07096636bd644803bc3f44622a26f8a7 P 4903f51b9dfc4f35aec8123e5f2034a0: Deleting log segment in path: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515571797997-16945-0/minicluster-data/ts-0-root/wals/07096636bd644803bc3f44622a26f8a7/wal-000000004 (ops 17-21)
I20260812 06:19:33.459986 17106 log.cc:1079] T 07096636bd644803bc3f44622a26f8a7 P 4903f51b9dfc4f35aec8123e5f2034a0: Deleting log segment in path: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515571797997-16945-0/minicluster-data/ts-0-root/wals/07096636bd644803bc3f44622a26f8a7/wal-000000005 (ops 22-26)
I20260812 06:19:33.460019 17106 log.cc:1079] T 07096636bd644803bc3f44622a26f8a7 P 4903f51b9dfc4f35aec8123e5f2034a0: Deleting log segment in path: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515571797997-16945-0/minicluster-data/ts-0-root/wals/07096636bd644803bc3f44622a26f8a7/wal-000000006 (ops 27-30)
I20260812 06:19:33.460050 17106 log.cc:1079] T 07096636bd644803bc3f44622a26f8a7 P 4903f51b9dfc4f35aec8123e5f2034a0: Deleting log segment in path: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515571797997-16945-0/minicluster-data/ts-0-root/wals/07096636bd644803bc3f44622a26f8a7/wal-000000007 (ops 31-35)
I20260812 06:19:33.460080 17106 log.cc:1079] T 07096636bd644803bc3f44622a26f8a7 P 4903f51b9dfc4f35aec8123e5f2034a0: Deleting log segment in path: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515571797997-16945-0/minicluster-data/ts-0-root/wals/07096636bd644803bc3f44622a26f8a7/wal-000000008 (ops 36-40)
I20260812 06:19:33.460110 17106 log.cc:1079] T 07096636bd644803bc3f44622a26f8a7 P 4903f51b9dfc4f35aec8123e5f2034a0: Deleting log segment in path: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515571797997-16945-0/minicluster-data/ts-0-root/wals/07096636bd644803bc3f44622a26f8a7/wal-000000009 (ops 41-45)
I20260812 06:19:33.460139 17106 log.cc:1079] T 07096636bd644803bc3f44622a26f8a7 P 4903f51b9dfc4f35aec8123e5f2034a0: Deleting log segment in path: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515571797997-16945-0/minicluster-data/ts-0-root/wals/07096636bd644803bc3f44622a26f8a7/wal-000000010 (ops 46-50)
I20260812 06:19:33.460168 17106 log.cc:1079] T 07096636bd644803bc3f44622a26f8a7 P 4903f51b9dfc4f35aec8123e5f2034a0: Deleting log segment in path: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515571797997-16945-0/minicluster-data/ts-0-root/wals/07096636bd644803bc3f44622a26f8a7/wal-000000011 (ops 51-55)
I20260812 06:19:33.460198 17106 log.cc:1079] T 07096636bd644803bc3f44622a26f8a7 P 4903f51b9dfc4f35aec8123e5f2034a0: Deleting log segment in path: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515571797997-16945-0/minicluster-data/ts-0-root/wals/07096636bd644803bc3f44622a26f8a7/wal-000000012 (ops 56-60)
I20260812 06:19:33.460227 17106 log.cc:1079] T 07096636bd644803bc3f44622a26f8a7 P 4903f51b9dfc4f35aec8123e5f2034a0: Deleting log segment in path: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515571797997-16945-0/minicluster-data/ts-0-root/wals/07096636bd644803bc3f44622a26f8a7/wal-000000013 (ops 61-64)
I20260812 06:19:33.477481 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: LogGCOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.018s	user 0.000s	sys 0.015s Metrics: {}
I20260812 06:19:33.477931 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling UndoDeltaBlockGCOp(07096636bd644803bc3f44622a26f8a7): 447 bytes on disk
I20260812 06:19:33.478494 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: UndoDeltaBlockGCOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":85,"lbm_reads_lt_1ms":4}
I20260812 06:19:33.479035 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7): perf score=2.188937
I20260812 06:19:33.502266 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.023s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5314,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:33.502677 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7): perf score=2.188937
I20260812 06:19:33.515442 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.013s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4458,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:33.515903 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling MajorDeltaCompactionOp(07096636bd644803bc3f44622a26f8a7): perf score=1.000000
I20260812 06:19:33.697152 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: MajorDeltaCompactionOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.181s	user 0.106s	sys 0.072s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877340,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":585,"lbm_read_time_us":11181,"lbm_reads_lt_1ms":674,"lbm_write_time_us":31390,"lbm_writes_lt_1ms":643,"mutex_wait_us":45,"peak_mem_usage":75542472,"reinsert_count":0,"thread_start_us":71,"threads_started":1,"update_count":3000}
I20260812 06:19:33.697652 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7): perf score=14.095187
I20260812 06:19:33.738070 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.040s	user 0.021s	sys 0.016s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":18049,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:33.738513 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling MajorDeltaCompactionOp(07096636bd644803bc3f44622a26f8a7): perf score=1.000000
I20260812 06:19:33.872010 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: MajorDeltaCompactionOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.133s	user 0.079s	sys 0.054s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672156,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":197,"lbm_read_time_us":9911,"lbm_reads_lt_1ms":467,"lbm_write_time_us":21877,"lbm_writes_lt_1ms":443,"mutex_wait_us":34,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":19712,"update_count":2000}
I20260812 06:19:33.872789 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7): perf score=10.126437
I20260812 06:19:33.908064 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.035s	user 0.020s	sys 0.013s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14975,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":1500}
I20260812 06:19:33.908491 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7): perf score=2.188937
I20260812 06:19:33.918632 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3884,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:33.919180 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling MajorDeltaCompactionOp(07096636bd644803bc3f44622a26f8a7): perf score=1.000000
I20260812 06:19:34.040323 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: MajorDeltaCompactionOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.121s	user 0.096s	sys 0.025s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":169,"lbm_read_time_us":8065,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23559,"lbm_writes_lt_1ms":443,"mutex_wait_us":24,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5376,"update_count":2000}
I20260812 06:19:34.040851 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7): perf score=10.126437
I20260812 06:19:34.081787 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.041s	user 0.017s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":11955,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:34.082229 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7): perf score=2.188937
I20260812 06:19:34.092470 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3828,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:34.093119 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling MajorDeltaCompactionOp(07096636bd644803bc3f44622a26f8a7): perf score=1.000000
I20260812 06:19:34.207141 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: MajorDeltaCompactionOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.114s	user 0.096s	sys 0.017s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":191,"lbm_read_time_us":9089,"lbm_reads_lt_1ms":472,"lbm_write_time_us":19028,"lbm_writes_lt_1ms":443,"mutex_wait_us":22,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7040,"update_count":2000}
I20260812 06:19:34.207654 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7): perf score=10.126437
I20260812 06:19:34.248854 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.041s	user 0.011s	sys 0.016s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":12485,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:34.249401 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7): perf score=2.188937
I20260812 06:19:34.259647 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3835,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:34.260262 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling MajorDeltaCompactionOp(07096636bd644803bc3f44622a26f8a7): perf score=1.000000
I20260812 06:19:34.367537 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: MajorDeltaCompactionOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.107s	user 0.087s	sys 0.019s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":880,"lbm_read_time_us":7148,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20551,"lbm_writes_lt_1ms":443,"mutex_wait_us":262,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:34.368108 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7): perf score=10.126437
I20260812 06:19:34.408239 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.040s	user 0.031s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14553,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:34.408784 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7): perf score=2.188937
I20260812 06:19:34.419221 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4020,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:34.419788 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling MajorDeltaCompactionOp(07096636bd644803bc3f44622a26f8a7): perf score=1.000000
I20260812 06:19:34.545702 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: MajorDeltaCompactionOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.126s	user 0.093s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1582,"lbm_read_time_us":9290,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20067,"lbm_writes_lt_1ms":443,"mutex_wait_us":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:34.546314 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7): perf score=10.126437
I20260812 06:19:34.574996 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.028s	user 0.020s	sys 0.007s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":12248,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:34.575508 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7): perf score=2.188937
I20260812 06:19:34.589283 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.014s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5218,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:34.589757 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling MajorDeltaCompactionOp(07096636bd644803bc3f44622a26f8a7): perf score=1.000000
I20260812 06:19:34.704386 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: MajorDeltaCompactionOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.114s	user 0.093s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":147,"lbm_read_time_us":7138,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22419,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:19:34.704993 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7): perf score=10.126437
I20260812 06:19:34.746987 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.042s	user 0.023s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12890,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:34.747537 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7): perf score=2.188937
I20260812 06:19:34.757200 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3587,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:34.757865 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling FlushMRSOp(07096636bd644803bc3f44622a26f8a7): perf score=1.000000
I20260812 06:19:34.788908 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: FlushMRSOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.031s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":64,"dirs.run_cpu_time_us":227,"dirs.run_wall_time_us":1455,"drs_written":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1354,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:34.789589 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling LogGCOp(07096636bd644803bc3f44622a26f8a7): free 121006434 bytes of WAL
I20260812 06:19:34.789795 17106 log_reader.cc:385] T 07096636bd644803bc3f44622a26f8a7: removed 12 log segments from log reader
I20260812 06:19:34.789842 17106 log.cc:1079] T 07096636bd644803bc3f44622a26f8a7 P 4903f51b9dfc4f35aec8123e5f2034a0: Deleting log segment in path: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515571797997-16945-0/minicluster-data/ts-0-root/wals/07096636bd644803bc3f44622a26f8a7/wal-000000014 (ops 65-69)
I20260812 06:19:34.789870 17106 log.cc:1079] T 07096636bd644803bc3f44622a26f8a7 P 4903f51b9dfc4f35aec8123e5f2034a0: Deleting log segment in path: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515571797997-16945-0/minicluster-data/ts-0-root/wals/07096636bd644803bc3f44622a26f8a7/wal-000000015 (ops 70-74)
I20260812 06:19:34.789899 17106 log.cc:1079] T 07096636bd644803bc3f44622a26f8a7 P 4903f51b9dfc4f35aec8123e5f2034a0: Deleting log segment in path: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515571797997-16945-0/minicluster-data/ts-0-root/wals/07096636bd644803bc3f44622a26f8a7/wal-000000016 (ops 75-79)
I20260812 06:19:34.789930 17106 log.cc:1079] T 07096636bd644803bc3f44622a26f8a7 P 4903f51b9dfc4f35aec8123e5f2034a0: Deleting log segment in path: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515571797997-16945-0/minicluster-data/ts-0-root/wals/07096636bd644803bc3f44622a26f8a7/wal-000000017 (ops 80-84)
I20260812 06:19:34.789963 17106 log.cc:1079] T 07096636bd644803bc3f44622a26f8a7 P 4903f51b9dfc4f35aec8123e5f2034a0: Deleting log segment in path: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515571797997-16945-0/minicluster-data/ts-0-root/wals/07096636bd644803bc3f44622a26f8a7/wal-000000018 (ops 85-89)
I20260812 06:19:34.790006 17106 log.cc:1079] T 07096636bd644803bc3f44622a26f8a7 P 4903f51b9dfc4f35aec8123e5f2034a0: Deleting log segment in path: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515571797997-16945-0/minicluster-data/ts-0-root/wals/07096636bd644803bc3f44622a26f8a7/wal-000000019 (ops 90-94)
I20260812 06:19:34.790023 17106 log.cc:1079] T 07096636bd644803bc3f44622a26f8a7 P 4903f51b9dfc4f35aec8123e5f2034a0: Deleting log segment in path: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515571797997-16945-0/minicluster-data/ts-0-root/wals/07096636bd644803bc3f44622a26f8a7/wal-000000020 (ops 95-99)
I20260812 06:19:34.790053 17106 log.cc:1079] T 07096636bd644803bc3f44622a26f8a7 P 4903f51b9dfc4f35aec8123e5f2034a0: Deleting log segment in path: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515571797997-16945-0/minicluster-data/ts-0-root/wals/07096636bd644803bc3f44622a26f8a7/wal-000000021 (ops 100-104)
I20260812 06:19:34.790098 17106 log.cc:1079] T 07096636bd644803bc3f44622a26f8a7 P 4903f51b9dfc4f35aec8123e5f2034a0: Deleting log segment in path: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515571797997-16945-0/minicluster-data/ts-0-root/wals/07096636bd644803bc3f44622a26f8a7/wal-000000022 (ops 105-108)
I20260812 06:19:34.790131 17106 log.cc:1079] T 07096636bd644803bc3f44622a26f8a7 P 4903f51b9dfc4f35aec8123e5f2034a0: Deleting log segment in path: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515571797997-16945-0/minicluster-data/ts-0-root/wals/07096636bd644803bc3f44622a26f8a7/wal-000000023 (ops 109-113)
I20260812 06:19:34.790163 17106 log.cc:1079] T 07096636bd644803bc3f44622a26f8a7 P 4903f51b9dfc4f35aec8123e5f2034a0: Deleting log segment in path: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515571797997-16945-0/minicluster-data/ts-0-root/wals/07096636bd644803bc3f44622a26f8a7/wal-000000024 (ops 114-118)
I20260812 06:19:34.790195 17106 log.cc:1079] T 07096636bd644803bc3f44622a26f8a7 P 4903f51b9dfc4f35aec8123e5f2034a0: Deleting log segment in path: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515571797997-16945-0/minicluster-data/ts-0-root/wals/07096636bd644803bc3f44622a26f8a7/wal-000000025 (ops 119-123)
I20260812 06:19:34.812083 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: LogGCOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.022s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:19:34.812506 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling UndoDeltaBlockGCOp(07096636bd644803bc3f44622a26f8a7): 472 bytes on disk
I20260812 06:19:34.812978 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: UndoDeltaBlockGCOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":68,"lbm_reads_lt_1ms":4}
I20260812 06:19:34.813504 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7): perf score=3.181125
I20260812 06:19:34.825139 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4349,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:34.825519 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7): perf score=2.188937
I20260812 06:19:34.838658 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4774,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:34.839167 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling MajorDeltaCompactionOp(07096636bd644803bc3f44622a26f8a7): perf score=1.000000
I20260812 06:19:35.011473 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: MajorDeltaCompactionOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.172s	user 0.128s	sys 0.035s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877325,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":11189,"lbm_read_time_us":12576,"lbm_reads_lt_1ms":674,"lbm_write_time_us":31729,"lbm_writes_lt_1ms":643,"mutex_wait_us":2299,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2688,"thread_start_us":77,"threads_started":1,"update_count":3000}
I20260812 06:19:35.012109 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7): perf score=14.095187
I20260812 06:19:35.052726 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.040s	user 0.027s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17609,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:35.053263 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7): perf score=2.188937
I20260812 06:19:35.063951 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.010s	user 0.004s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3939,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:35.064623 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling MajorDeltaCompactionOp(07096636bd644803bc3f44622a26f8a7): perf score=1.000000
I20260812 06:19:35.201391 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: MajorDeltaCompactionOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.137s	user 0.114s	sys 0.022s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1381,"lbm_read_time_us":10780,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25747,"lbm_writes_lt_1ms":543,"mutex_wait_us":463,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2500}
I20260812 06:19:35.201963 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7): perf score=10.126437
I20260812 06:19:35.235299 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.033s	user 0.020s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13529,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:35.235816 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7): perf score=2.188937
I20260812 06:19:35.245421 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3563,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:35.245994 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling MajorDeltaCompactionOp(07096636bd644803bc3f44622a26f8a7): perf score=1.000000
I20260812 06:19:35.363468 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: MajorDeltaCompactionOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.117s	user 0.089s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":219,"lbm_read_time_us":7958,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22360,"lbm_writes_lt_1ms":443,"mutex_wait_us":28,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3968,"update_count":2000}
I20260812 06:19:35.364066 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7): perf score=10.126437
I20260812 06:19:35.403626 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.039s	user 0.018s	sys 0.019s Metrics: {"bytes_written":12307494,"delete_count":0,"lbm_write_time_us":13056,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:35.404209 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7): perf score=2.188937
I20260812 06:19:35.414196 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3833,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:35.414703 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling MajorDeltaCompactionOp(07096636bd644803bc3f44622a26f8a7): perf score=1.000000
I20260812 06:19:35.558265 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: MajorDeltaCompactionOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.143s	user 0.097s	sys 0.045s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672281,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":543,"lbm_read_time_us":10923,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23315,"lbm_writes_lt_1ms":443,"mutex_wait_us":279,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3456,"update_count":2000}
I20260812 06:19:35.558753 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7): perf score=10.126437
I20260812 06:19:35.598802 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.040s	user 0.014s	sys 0.013s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":12838,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":1500}
I20260812 06:19:35.599316 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7): perf score=2.188937
I20260812 06:19:35.609264 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3840,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:35.609838 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling MajorDeltaCompactionOp(07096636bd644803bc3f44622a26f8a7): perf score=1.000000
I20260812 06:19:35.730705 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: MajorDeltaCompactionOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.121s	user 0.104s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":607,"lbm_read_time_us":9362,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21983,"lbm_writes_lt_1ms":443,"mutex_wait_us":270,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":44672,"update_count":2000}
I20260812 06:19:35.731271 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7): perf score=10.126437
I20260812 06:19:35.765902 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.034s	user 0.019s	sys 0.008s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":12763,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:35.766420 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7): perf score=2.188937
I20260812 06:19:35.781140 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5382,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:35.781664 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling MajorDeltaCompactionOp(07096636bd644803bc3f44622a26f8a7): perf score=1.000000
I20260812 06:19:35.900319 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: MajorDeltaCompactionOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.118s	user 0.091s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":263,"lbm_read_time_us":7564,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23144,"lbm_writes_lt_1ms":443,"mutex_wait_us":64,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:35.900916 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7): perf score=10.126437
I20260812 06:19:35.944442 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.043s	user 0.033s	sys 0.003s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16319,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:35.944878 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7): perf score=2.188937
I20260812 06:19:35.955931 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4071,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:35.956460 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling MajorDeltaCompactionOp(07096636bd644803bc3f44622a26f8a7): perf score=1.000000
I20260812 06:19:36.082257 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: MajorDeltaCompactionOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.126s	user 0.108s	sys 0.018s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":671,"lbm_read_time_us":10840,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23735,"lbm_writes_lt_1ms":443,"mutex_wait_us":271,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:19:36.082921 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7): perf score=10.126437
I20260812 06:19:36.134893 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.052s	user 0.043s	sys 0.008s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":19039,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:36.135414 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7): perf score=2.188937
I20260812 06:19:36.146417 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4205,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:36.147011 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling FlushMRSOp(07096636bd644803bc3f44622a26f8a7): perf score=1.000000
I20260812 06:19:36.185425 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: FlushMRSOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.038s	user 0.027s	sys 0.001s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":65,"dirs.run_cpu_time_us":203,"dirs.run_wall_time_us":1305,"drs_written":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1618,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:36.186131 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling LogGCOp(07096636bd644803bc3f44622a26f8a7): free 133024572 bytes of WAL
I20260812 06:19:36.186383 17106 log_reader.cc:385] T 07096636bd644803bc3f44622a26f8a7: removed 13 log segments from log reader
I20260812 06:19:36.186439 17106 log.cc:1079] T 07096636bd644803bc3f44622a26f8a7 P 4903f51b9dfc4f35aec8123e5f2034a0: Deleting log segment in path: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515571797997-16945-0/minicluster-data/ts-0-root/wals/07096636bd644803bc3f44622a26f8a7/wal-000000026 (ops 124-128)
I20260812 06:19:36.186471 17106 log.cc:1079] T 07096636bd644803bc3f44622a26f8a7 P 4903f51b9dfc4f35aec8123e5f2034a0: Deleting log segment in path: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515571797997-16945-0/minicluster-data/ts-0-root/wals/07096636bd644803bc3f44622a26f8a7/wal-000000027 (ops 129-133)
I20260812 06:19:36.186508 17106 log.cc:1079] T 07096636bd644803bc3f44622a26f8a7 P 4903f51b9dfc4f35aec8123e5f2034a0: Deleting log segment in path: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515571797997-16945-0/minicluster-data/ts-0-root/wals/07096636bd644803bc3f44622a26f8a7/wal-000000028 (ops 134-138)
I20260812 06:19:36.186546 17106 log.cc:1079] T 07096636bd644803bc3f44622a26f8a7 P 4903f51b9dfc4f35aec8123e5f2034a0: Deleting log segment in path: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515571797997-16945-0/minicluster-data/ts-0-root/wals/07096636bd644803bc3f44622a26f8a7/wal-000000029 (ops 139-143)
I20260812 06:19:36.186576 17106 log.cc:1079] T 07096636bd644803bc3f44622a26f8a7 P 4903f51b9dfc4f35aec8123e5f2034a0: Deleting log segment in path: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515571797997-16945-0/minicluster-data/ts-0-root/wals/07096636bd644803bc3f44622a26f8a7/wal-000000030 (ops 144-148)
I20260812 06:19:36.186614 17106 log.cc:1079] T 07096636bd644803bc3f44622a26f8a7 P 4903f51b9dfc4f35aec8123e5f2034a0: Deleting log segment in path: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515571797997-16945-0/minicluster-data/ts-0-root/wals/07096636bd644803bc3f44622a26f8a7/wal-000000031 (ops 149-153)
I20260812 06:19:36.186653 17106 log.cc:1079] T 07096636bd644803bc3f44622a26f8a7 P 4903f51b9dfc4f35aec8123e5f2034a0: Deleting log segment in path: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515571797997-16945-0/minicluster-data/ts-0-root/wals/07096636bd644803bc3f44622a26f8a7/wal-000000032 (ops 154-158)
I20260812 06:19:36.186691 17106 log.cc:1079] T 07096636bd644803bc3f44622a26f8a7 P 4903f51b9dfc4f35aec8123e5f2034a0: Deleting log segment in path: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515571797997-16945-0/minicluster-data/ts-0-root/wals/07096636bd644803bc3f44622a26f8a7/wal-000000033 (ops 159-162)
I20260812 06:19:36.186729 17106 log.cc:1079] T 07096636bd644803bc3f44622a26f8a7 P 4903f51b9dfc4f35aec8123e5f2034a0: Deleting log segment in path: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515571797997-16945-0/minicluster-data/ts-0-root/wals/07096636bd644803bc3f44622a26f8a7/wal-000000034 (ops 163-167)
I20260812 06:19:36.186769 17106 log.cc:1079] T 07096636bd644803bc3f44622a26f8a7 P 4903f51b9dfc4f35aec8123e5f2034a0: Deleting log segment in path: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515571797997-16945-0/minicluster-data/ts-0-root/wals/07096636bd644803bc3f44622a26f8a7/wal-000000035 (ops 168-172)
I20260812 06:19:36.186807 17106 log.cc:1079] T 07096636bd644803bc3f44622a26f8a7 P 4903f51b9dfc4f35aec8123e5f2034a0: Deleting log segment in path: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515571797997-16945-0/minicluster-data/ts-0-root/wals/07096636bd644803bc3f44622a26f8a7/wal-000000036 (ops 173-177)
I20260812 06:19:36.186877 17106 log.cc:1079] T 07096636bd644803bc3f44622a26f8a7 P 4903f51b9dfc4f35aec8123e5f2034a0: Deleting log segment in path: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515571797997-16945-0/minicluster-data/ts-0-root/wals/07096636bd644803bc3f44622a26f8a7/wal-000000037 (ops 178-182)
I20260812 06:19:36.186918 17106 log.cc:1079] T 07096636bd644803bc3f44622a26f8a7 P 4903f51b9dfc4f35aec8123e5f2034a0: Deleting log segment in path: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515571797997-16945-0/minicluster-data/ts-0-root/wals/07096636bd644803bc3f44622a26f8a7/wal-000000038 (ops 183-187)
I20260812 06:19:36.209262 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: LogGCOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.023s	user 0.001s	sys 0.019s Metrics: {}
I20260812 06:19:36.209682 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7): perf score=3.181125
I20260812 06:19:36.231575 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.022s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":5227,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:36.232048 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling UndoDeltaBlockGCOp(07096636bd644803bc3f44622a26f8a7): 482 bytes on disk
I20260812 06:19:36.232484 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: UndoDeltaBlockGCOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4}
I20260812 06:19:36.233070 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7): perf score=2.188937
I20260812 06:19:36.243453 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.010s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3585,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:36.244062 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling MajorDeltaCompactionOp(07096636bd644803bc3f44622a26f8a7): perf score=1.000000
I20260812 06:19:36.444418 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: MajorDeltaCompactionOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.200s	user 0.141s	sys 0.059s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877327,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":405,"lbm_read_time_us":14689,"lbm_reads_lt_1ms":674,"lbm_write_time_us":36656,"lbm_writes_lt_1ms":643,"mutex_wait_us":68,"peak_mem_usage":75542472,"reinsert_count":0,"thread_start_us":89,"threads_started":1,"update_count":3000}
I20260812 06:19:36.445060 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7): perf score=14.095187
I20260812 06:19:36.495698 16945 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.446s	user 1.617s	sys 0.123s
I20260812 06:19:36.498694 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.053s	user 0.030s	sys 0.011s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20520,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:36.499188 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7): perf score=2.188937
I20260812 06:19:36.508327 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: FlushDeltaMemStoresOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3763,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:36.508713 17200 maintenance_manager.cc:419] P 4903f51b9dfc4f35aec8123e5f2034a0: Scheduling MajorDeltaCompactionOp(07096636bd644803bc3f44622a26f8a7): perf score=1.000000
I20260812 06:19:36.554000 16945 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.058s	user 0.001s	sys 0.000s
I20260812 06:19:36.554590 16945 tablet_server.cc:179] TabletServer@127.16.140.65:0 shutting down...
I20260812 06:19:36.633044 17106 maintenance_manager.cc:643] P 4903f51b9dfc4f35aec8123e5f2034a0: MajorDeltaCompactionOp(07096636bd644803bc3f44622a26f8a7) complete. Timing: real 0.124s	user 0.068s	sys 0.056s Metrics: {"cfile_cache_hit":244,"cfile_cache_hit_bytes":9971041,"cfile_cache_miss":288,"cfile_cache_miss_bytes":14803648,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":280,"lbm_read_time_us":5950,"lbm_reads_lt_1ms":320,"lbm_write_time_us":23341,"lbm_writes_lt_1ms":543,"mutex_wait_us":41,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":51584,"update_count":2500}
I20260812 06:19:36.634039 16945 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:36.634476 16945 tablet_replica.cc:333] T 07096636bd644803bc3f44622a26f8a7 P 4903f51b9dfc4f35aec8123e5f2034a0: stopping tablet replica
I20260812 06:19:36.634711 16945 raft_consensus.cc:2243] T 07096636bd644803bc3f44622a26f8a7 P 4903f51b9dfc4f35aec8123e5f2034a0 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:36.634958 16945 raft_consensus.cc:2272] T 07096636bd644803bc3f44622a26f8a7 P 4903f51b9dfc4f35aec8123e5f2034a0 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:36.650038 16945 tablet_server.cc:196] TabletServer@127.16.140.65:0 shutdown complete.
I20260812 06:19:36.679844 16945 master.cc:562] Master@127.16.140.126:39871 shutting down...
I20260812 06:19:36.683032 16945 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 287f51b0a2f444238a1169eaa44f974f [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:36.683194 16945 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 287f51b0a2f444238a1169eaa44f974f [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:36.683270 16945 tablet_replica.cc:333] T 00000000000000000000000000000000 P 287f51b0a2f444238a1169eaa44f974f: stopping tablet replica
I20260812 06:19:36.695329 16945 master.cc:584] Master@127.16.140.126:39871 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (4957 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:19:36.775522 16945 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.16.140.126:44679
I20260812 06:19:36.775934 16945 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:36.777976 17246 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:36.777983 16945 server_base.cc:1061] running on GCE node
W20260812 06:19:36.778081 17243 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:36.778081 17244 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:36.778388 16945 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:36.778434 16945 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:36.778455 16945 hybrid_clock.cc:648] HybridClock initialized: now 1786515576778455 us; error 0 us; skew 500 ppm
I20260812 06:19:36.779232 16945 webserver.cc:533] Webserver started at http://127.16.140.126:37581/ using document root <none> and password file <none>
I20260812 06:19:36.779377 16945 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:36.779423 16945 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:36.779515 16945 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:36.779871 16945 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515571797997-16945-0/minicluster-data/master-0-root/instance:
uuid: "3241aff3f6474320a0ac0469469ca3ea"
format_stamp: "Formatted at 2026-08-12 06:19:36 on dist-test-slave-5bn2"
I20260812 06:19:36.781240 16945 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:36.782083 17253 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:36.782286 16945 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:36.782356 16945 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515571797997-16945-0/minicluster-data/master-0-root
uuid: "3241aff3f6474320a0ac0469469ca3ea"
format_stamp: "Formatted at 2026-08-12 06:19:36 on dist-test-slave-5bn2"
I20260812 06:19:36.782423 16945 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515571797997-16945-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515571797997-16945-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515571797997-16945-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:36.790674 16945 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:36.791020 16945 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:36.794812 16945 rpc_server.cc:307] RPC server started. Bound to: 127.16.140.126:44679
I20260812 06:19:36.796653 17334 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.16.140.126:44679 every 8 connection(s)
I20260812 06:19:36.797065 17337 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:36.798810 17337 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 3241aff3f6474320a0ac0469469ca3ea: Bootstrap starting.
I20260812 06:19:36.799546 17337 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 3241aff3f6474320a0ac0469469ca3ea: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:36.800413 17337 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 3241aff3f6474320a0ac0469469ca3ea: No bootstrap required, opened a new log
I20260812 06:19:36.800751 17337 raft_consensus.cc:359] T 00000000000000000000000000000000 P 3241aff3f6474320a0ac0469469ca3ea [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3241aff3f6474320a0ac0469469ca3ea" member_type: VOTER }
I20260812 06:19:36.800828 17337 raft_consensus.cc:385] T 00000000000000000000000000000000 P 3241aff3f6474320a0ac0469469ca3ea [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:36.800853 17337 raft_consensus.cc:740] T 00000000000000000000000000000000 P 3241aff3f6474320a0ac0469469ca3ea [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 3241aff3f6474320a0ac0469469ca3ea, State: Initialized, Role: FOLLOWER
I20260812 06:19:36.800969 17337 consensus_queue.cc:260] T 00000000000000000000000000000000 P 3241aff3f6474320a0ac0469469ca3ea [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: "3241aff3f6474320a0ac0469469ca3ea" member_type: VOTER }
I20260812 06:19:36.801028 17337 raft_consensus.cc:399] T 00000000000000000000000000000000 P 3241aff3f6474320a0ac0469469ca3ea [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:36.801054 17337 raft_consensus.cc:493] T 00000000000000000000000000000000 P 3241aff3f6474320a0ac0469469ca3ea [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:36.801085 17337 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 3241aff3f6474320a0ac0469469ca3ea [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:36.801669 17337 raft_consensus.cc:515] T 00000000000000000000000000000000 P 3241aff3f6474320a0ac0469469ca3ea [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3241aff3f6474320a0ac0469469ca3ea" member_type: VOTER }
I20260812 06:19:36.801775 17337 leader_election.cc:304] T 00000000000000000000000000000000 P 3241aff3f6474320a0ac0469469ca3ea [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: 3241aff3f6474320a0ac0469469ca3ea; no voters: 
I20260812 06:19:36.801904 17337 leader_election.cc:290] T 00000000000000000000000000000000 P 3241aff3f6474320a0ac0469469ca3ea [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:36.802006 17343 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 3241aff3f6474320a0ac0469469ca3ea [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:36.802187 17343 raft_consensus.cc:697] T 00000000000000000000000000000000 P 3241aff3f6474320a0ac0469469ca3ea [term 1 LEADER]: Becoming Leader. State: Replica: 3241aff3f6474320a0ac0469469ca3ea, State: Running, Role: LEADER
I20260812 06:19:36.802307 17337 sys_catalog.cc:565] T 00000000000000000000000000000000 P 3241aff3f6474320a0ac0469469ca3ea [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:36.802331 17343 consensus_queue.cc:237] T 00000000000000000000000000000000 P 3241aff3f6474320a0ac0469469ca3ea [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: "3241aff3f6474320a0ac0469469ca3ea" member_type: VOTER }
I20260812 06:19:36.802728 17347 sys_catalog.cc:455] T 00000000000000000000000000000000 P 3241aff3f6474320a0ac0469469ca3ea [sys.catalog]: SysCatalogTable state changed. Reason: New leader 3241aff3f6474320a0ac0469469ca3ea. Latest consensus state: current_term: 1 leader_uuid: "3241aff3f6474320a0ac0469469ca3ea" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3241aff3f6474320a0ac0469469ca3ea" member_type: VOTER } }
I20260812 06:19:36.802716 17346 sys_catalog.cc:455] T 00000000000000000000000000000000 P 3241aff3f6474320a0ac0469469ca3ea [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "3241aff3f6474320a0ac0469469ca3ea" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3241aff3f6474320a0ac0469469ca3ea" member_type: VOTER } }
I20260812 06:19:36.802829 17346 sys_catalog.cc:458] T 00000000000000000000000000000000 P 3241aff3f6474320a0ac0469469ca3ea [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:36.802819 17347 sys_catalog.cc:458] T 00000000000000000000000000000000 P 3241aff3f6474320a0ac0469469ca3ea [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:36.803128 17352 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:36.803951 17352 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:36.804144 16945 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:36.805613 17352 catalog_manager.cc:1383] Generated new cluster ID: 2a68099bc676436082b00e4bd2989a1d
I20260812 06:19:36.805661 17352 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:36.810029 17352 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:36.810521 17352 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:36.819173 17352 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 3241aff3f6474320a0ac0469469ca3ea: Generated new TSK 0
I20260812 06:19:36.819322 17352 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:36.836330 16945 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:36.838120 17371 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:36.838212 17368 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:36.838272 16945 server_base.cc:1061] running on GCE node
W20260812 06:19:36.838122 17369 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:36.838551 16945 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:36.838596 16945 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:36.838610 16945 hybrid_clock.cc:648] HybridClock initialized: now 1786515576838611 us; error 0 us; skew 500 ppm
I20260812 06:19:36.839395 16945 webserver.cc:533] Webserver started at http://127.16.140.65:35943/ using document root <none> and password file <none>
I20260812 06:19:36.839526 16945 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:36.839565 16945 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:36.839619 16945 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:36.839941 16945 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515571797997-16945-0/minicluster-data/ts-0-root/instance:
uuid: "ed45f7ed68e348ba8c41a1e1590b5678"
format_stamp: "Formatted at 2026-08-12 06:19:36 on dist-test-slave-5bn2"
I20260812 06:19:36.841253 16945 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:36.842046 17377 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:36.842289 16945 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:36.842357 16945 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515571797997-16945-0/minicluster-data/ts-0-root
uuid: "ed45f7ed68e348ba8c41a1e1590b5678"
format_stamp: "Formatted at 2026-08-12 06:19:36 on dist-test-slave-5bn2"
I20260812 06:19:36.842422 16945 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515571797997-16945-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515571797997-16945-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515571797997-16945-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:36.852010 16945 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:36.852293 16945 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:36.852545 16945 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:36.852949 16945 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:36.852988 16945 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:36.853029 16945 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:36.853055 16945 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:36.856946 16945 rpc_server.cc:307] RPC server started. Bound to: 127.16.140.65:33475
I20260812 06:19:36.857988 17479 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.16.140.65:33475 every 8 connection(s)
I20260812 06:19:36.861914 17481 heartbeater.cc:344] Connected to a master server at 127.16.140.126:44679
I20260812 06:19:36.862001 17481 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:36.862190 17481 heartbeater.cc:507] Master 127.16.140.126:44679 requested a full tablet report, sending...
I20260812 06:19:36.862746 17278 ts_manager.cc:194] Registered new tserver with Master: ed45f7ed68e348ba8c41a1e1590b5678 (127.16.140.65:33475)
I20260812 06:19:36.863111 16945 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.005518145s
I20260812 06:19:36.863489 17278 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:35750
I20260812 06:19:36.870253 17278 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:35760:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:36.877957 17426 tablet_service.cc:1511] Processing CreateTablet for tablet eba70b9d14374222911601482567e612 (DEFAULT_TABLE table=heavy-update-compaction-test [id=bcddda3d469844f588f9136ec9efdeac]), partition=
I20260812 06:19:36.878180 17426 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet eba70b9d14374222911601482567e612. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:36.879989 17496 tablet_bootstrap.cc:492] T eba70b9d14374222911601482567e612 P ed45f7ed68e348ba8c41a1e1590b5678: Bootstrap starting.
I20260812 06:19:36.880784 17496 tablet_bootstrap.cc:654] T eba70b9d14374222911601482567e612 P ed45f7ed68e348ba8c41a1e1590b5678: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:36.881646 17496 tablet_bootstrap.cc:492] T eba70b9d14374222911601482567e612 P ed45f7ed68e348ba8c41a1e1590b5678: No bootstrap required, opened a new log
I20260812 06:19:36.881723 17496 ts_tablet_manager.cc:1403] T eba70b9d14374222911601482567e612 P ed45f7ed68e348ba8c41a1e1590b5678: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:19:36.882057 17496 raft_consensus.cc:359] T eba70b9d14374222911601482567e612 P ed45f7ed68e348ba8c41a1e1590b5678 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ed45f7ed68e348ba8c41a1e1590b5678" member_type: VOTER last_known_addr { host: "127.16.140.65" port: 33475 } }
I20260812 06:19:36.882140 17496 raft_consensus.cc:385] T eba70b9d14374222911601482567e612 P ed45f7ed68e348ba8c41a1e1590b5678 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:36.882169 17496 raft_consensus.cc:740] T eba70b9d14374222911601482567e612 P ed45f7ed68e348ba8c41a1e1590b5678 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: ed45f7ed68e348ba8c41a1e1590b5678, State: Initialized, Role: FOLLOWER
I20260812 06:19:36.882284 17496 consensus_queue.cc:260] T eba70b9d14374222911601482567e612 P ed45f7ed68e348ba8c41a1e1590b5678 [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: "ed45f7ed68e348ba8c41a1e1590b5678" member_type: VOTER last_known_addr { host: "127.16.140.65" port: 33475 } }
I20260812 06:19:36.882351 17496 raft_consensus.cc:399] T eba70b9d14374222911601482567e612 P ed45f7ed68e348ba8c41a1e1590b5678 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:36.882390 17496 raft_consensus.cc:493] T eba70b9d14374222911601482567e612 P ed45f7ed68e348ba8c41a1e1590b5678 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:36.882436 17496 raft_consensus.cc:3060] T eba70b9d14374222911601482567e612 P ed45f7ed68e348ba8c41a1e1590b5678 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:36.883170 17496 raft_consensus.cc:515] T eba70b9d14374222911601482567e612 P ed45f7ed68e348ba8c41a1e1590b5678 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ed45f7ed68e348ba8c41a1e1590b5678" member_type: VOTER last_known_addr { host: "127.16.140.65" port: 33475 } }
I20260812 06:19:36.883314 17496 leader_election.cc:304] T eba70b9d14374222911601482567e612 P ed45f7ed68e348ba8c41a1e1590b5678 [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: ed45f7ed68e348ba8c41a1e1590b5678; no voters: 
I20260812 06:19:36.883517 17496 leader_election.cc:290] T eba70b9d14374222911601482567e612 P ed45f7ed68e348ba8c41a1e1590b5678 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:36.883606 17498 raft_consensus.cc:2804] T eba70b9d14374222911601482567e612 P ed45f7ed68e348ba8c41a1e1590b5678 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:36.883836 17498 raft_consensus.cc:697] T eba70b9d14374222911601482567e612 P ed45f7ed68e348ba8c41a1e1590b5678 [term 1 LEADER]: Becoming Leader. State: Replica: ed45f7ed68e348ba8c41a1e1590b5678, State: Running, Role: LEADER
I20260812 06:19:36.883857 17496 ts_tablet_manager.cc:1434] T eba70b9d14374222911601482567e612 P ed45f7ed68e348ba8c41a1e1590b5678: Time spent starting tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:36.883960 17498 consensus_queue.cc:237] T eba70b9d14374222911601482567e612 P ed45f7ed68e348ba8c41a1e1590b5678 [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: "ed45f7ed68e348ba8c41a1e1590b5678" member_type: VOTER last_known_addr { host: "127.16.140.65" port: 33475 } }
I20260812 06:19:36.884037 17481 heartbeater.cc:499] Master 127.16.140.126:44679 was elected leader, sending a full tablet report...
I20260812 06:19:36.885111 17278 catalog_manager.cc:5719] T eba70b9d14374222911601482567e612 P ed45f7ed68e348ba8c41a1e1590b5678 reported cstate change: term changed from 0 to 1, leader changed from <none> to ed45f7ed68e348ba8c41a1e1590b5678 (127.16.140.65). New cstate: current_term: 1 leader_uuid: "ed45f7ed68e348ba8c41a1e1590b5678" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ed45f7ed68e348ba8c41a1e1590b5678" member_type: VOTER last_known_addr { host: "127.16.140.65" port: 33475 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:36.937410 16945 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.049s	user 0.010s	sys 0.012s
I20260812 06:19:37.108307 17482 maintenance_manager.cc:419] P ed45f7ed68e348ba8c41a1e1590b5678: Scheduling FlushMRSOp(eba70b9d14374222911601482567e612): perf score=23.023690
I20260812 06:19:37.264542 17384 maintenance_manager.cc:643] P ed45f7ed68e348ba8c41a1e1590b5678: FlushMRSOp(eba70b9d14374222911601482567e612) complete. Timing: real 0.156s	user 0.118s	sys 0.036s Metrics: {"bytes_written":13538213,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":65,"dirs.run_cpu_time_us":198,"dirs.run_wall_time_us":801,"drs_written":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4,"lbm_write_time_us":39903,"lbm_writes_lt_1ms":897,"peak_mem_usage":0,"reinsert_count":0,"rows_written":106,"spinlock_wait_cycles":15360,"update_count":1650}
I20260812 06:19:37.265195 17482 maintenance_manager.cc:419] P ed45f7ed68e348ba8c41a1e1590b5678: Scheduling LogGCOp(eba70b9d14374222911601482567e612): free 32761802 bytes of WAL
I20260812 06:19:37.265419 17384 log_reader.cc:385] T eba70b9d14374222911601482567e612: removed 3 log segments from log reader
I20260812 06:19:37.265496 17384 log.cc:1079] T eba70b9d14374222911601482567e612 P ed45f7ed68e348ba8c41a1e1590b5678: Deleting log segment in path: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515571797997-16945-0/minicluster-data/ts-0-root/wals/eba70b9d14374222911601482567e612/wal-000000001 (ops 1-6)
I20260812 06:19:37.265529 17384 log.cc:1079] T eba70b9d14374222911601482567e612 P ed45f7ed68e348ba8c41a1e1590b5678: Deleting log segment in path: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515571797997-16945-0/minicluster-data/ts-0-root/wals/eba70b9d14374222911601482567e612/wal-000000002 (ops 7-11)
I20260812 06:19:37.265561 17384 log.cc:1079] T eba70b9d14374222911601482567e612 P ed45f7ed68e348ba8c41a1e1590b5678: Deleting log segment in path: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515571797997-16945-0/minicluster-data/ts-0-root/wals/eba70b9d14374222911601482567e612/wal-000000003 (ops 12-16)
I20260812 06:19:37.270830 17384 maintenance_manager.cc:643] P ed45f7ed68e348ba8c41a1e1590b5678: LogGCOp(eba70b9d14374222911601482567e612) complete. Timing: real 0.005s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:19:37.271279 17482 maintenance_manager.cc:419] P ed45f7ed68e348ba8c41a1e1590b5678: Scheduling FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612): perf score=3.181125
I20260812 06:19:37.282306 17384 maintenance_manager.cc:643] P ed45f7ed68e348ba8c41a1e1590b5678: FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612) complete. Timing: real 0.011s	user 0.003s	sys 0.006s Metrics: {"bytes_written":4307783,"delete_count":0,"lbm_write_time_us":4098,"lbm_writes_lt_1ms":108,"reinsert_count":0,"update_count":525}
I20260812 06:19:37.282698 17482 maintenance_manager.cc:419] P ed45f7ed68e348ba8c41a1e1590b5678: Scheduling FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612): perf score=1.196750
I20260812 06:19:37.291543 17384 maintenance_manager.cc:643] P ed45f7ed68e348ba8c41a1e1590b5678: FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":2256529,"delete_count":0,"lbm_write_time_us":2960,"lbm_writes_lt_1ms":58,"reinsert_count":0,"update_count":275}
I20260812 06:19:37.291949 17482 maintenance_manager.cc:419] P ed45f7ed68e348ba8c41a1e1590b5678: Scheduling MajorDeltaCompactionOp(eba70b9d14374222911601482567e612): perf score=1.000000
I20260812 06:19:37.468719 17384 maintenance_manager.cc:643] P ed45f7ed68e348ba8c41a1e1590b5678: MajorDeltaCompactionOp(eba70b9d14374222911601482567e612) complete. Timing: real 0.177s	user 0.111s	sys 0.059s Metrics: {"cfile_cache_miss":523,"cfile_cache_miss_bytes":24446490,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":464,"lbm_read_time_us":12794,"lbm_reads_lt_1ms":563,"lbm_write_time_us":27255,"lbm_writes_lt_1ms":533,"mutex_wait_us":46,"peak_mem_usage":61665166,"reinsert_count":0,"spinlock_wait_cycles":8960,"thread_start_us":306,"threads_started":5,"update_count":2450}
I20260812 06:19:37.469208 17482 maintenance_manager.cc:419] P ed45f7ed68e348ba8c41a1e1590b5678: Scheduling FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612): perf score=14.095187
I20260812 06:19:37.521275 17384 maintenance_manager.cc:643] P ed45f7ed68e348ba8c41a1e1590b5678: FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612) complete. Timing: real 0.052s	user 0.036s	sys 0.008s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":19446,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:37.521762 17482 maintenance_manager.cc:419] P ed45f7ed68e348ba8c41a1e1590b5678: Scheduling FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612): perf score=2.188937
I20260812 06:19:37.531574 17384 maintenance_manager.cc:643] P ed45f7ed68e348ba8c41a1e1590b5678: FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3706,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:37.531952 17482 maintenance_manager.cc:419] P ed45f7ed68e348ba8c41a1e1590b5678: Scheduling MajorDeltaCompactionOp(eba70b9d14374222911601482567e612): perf score=1.000000
I20260812 06:19:37.703693 17384 maintenance_manager.cc:643] P ed45f7ed68e348ba8c41a1e1590b5678: MajorDeltaCompactionOp(eba70b9d14374222911601482567e612) complete. Timing: real 0.172s	user 0.112s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24856655,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":96,"lbm_read_time_us":10868,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26435,"lbm_writes_lt_1ms":543,"mutex_wait_us":40,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10240,"update_count":2500}
I20260812 06:19:37.704257 17482 maintenance_manager.cc:419] P ed45f7ed68e348ba8c41a1e1590b5678: Scheduling FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612): perf score=14.095187
I20260812 06:19:37.754729 17384 maintenance_manager.cc:643] P ed45f7ed68e348ba8c41a1e1590b5678: FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612) complete. Timing: real 0.050s	user 0.024s	sys 0.019s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":16654,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:37.755249 17482 maintenance_manager.cc:419] P ed45f7ed68e348ba8c41a1e1590b5678: Scheduling FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612): perf score=2.188937
I20260812 06:19:37.765138 17384 maintenance_manager.cc:643] P ed45f7ed68e348ba8c41a1e1590b5678: FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3850,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:37.765636 17482 maintenance_manager.cc:419] P ed45f7ed68e348ba8c41a1e1590b5678: Scheduling MajorDeltaCompactionOp(eba70b9d14374222911601482567e612): perf score=1.000000
I20260812 06:19:37.943225 17384 maintenance_manager.cc:643] P ed45f7ed68e348ba8c41a1e1590b5678: MajorDeltaCompactionOp(eba70b9d14374222911601482567e612) complete. Timing: real 0.177s	user 0.117s	sys 0.051s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24856654,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":406,"lbm_read_time_us":11606,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28008,"lbm_writes_lt_1ms":543,"mutex_wait_us":39,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6016,"update_count":2500}
I20260812 06:19:37.943773 17482 maintenance_manager.cc:419] P ed45f7ed68e348ba8c41a1e1590b5678: Scheduling UndoDeltaBlockGCOp(eba70b9d14374222911601482567e612): 20924070 bytes on disk
I20260812 06:19:37.944183 17384 maintenance_manager.cc:643] P ed45f7ed68e348ba8c41a1e1590b5678: UndoDeltaBlockGCOp(eba70b9d14374222911601482567e612) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4}
I20260812 06:19:37.944602 17482 maintenance_manager.cc:419] P ed45f7ed68e348ba8c41a1e1590b5678: Scheduling FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612): perf score=14.095187
I20260812 06:19:38.002038 17384 maintenance_manager.cc:643] P ed45f7ed68e348ba8c41a1e1590b5678: FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612) complete. Timing: real 0.057s	user 0.035s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20790,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:38.002605 17482 maintenance_manager.cc:419] P ed45f7ed68e348ba8c41a1e1590b5678: Scheduling FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612): perf score=2.188937
I20260812 06:19:38.012676 17384 maintenance_manager.cc:643] P ed45f7ed68e348ba8c41a1e1590b5678: FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3800,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:38.013151 17482 maintenance_manager.cc:419] P ed45f7ed68e348ba8c41a1e1590b5678: Scheduling MajorDeltaCompactionOp(eba70b9d14374222911601482567e612): perf score=1.000000
I20260812 06:19:38.192162 17384 maintenance_manager.cc:643] P ed45f7ed68e348ba8c41a1e1590b5678: MajorDeltaCompactionOp(eba70b9d14374222911601482567e612) complete. Timing: real 0.179s	user 0.105s	sys 0.063s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24856653,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":599,"lbm_read_time_us":11490,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26581,"lbm_writes_lt_1ms":543,"mutex_wait_us":31,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14080,"update_count":2500}
I20260812 06:19:38.192687 17482 maintenance_manager.cc:419] P ed45f7ed68e348ba8c41a1e1590b5678: Scheduling FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612): perf score=14.095187
I20260812 06:19:38.241673 17384 maintenance_manager.cc:643] P ed45f7ed68e348ba8c41a1e1590b5678: FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612) complete. Timing: real 0.049s	user 0.025s	sys 0.015s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":18839,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2000}
I20260812 06:19:38.242233 17482 maintenance_manager.cc:419] P ed45f7ed68e348ba8c41a1e1590b5678: Scheduling FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612): perf score=2.188937
I20260812 06:19:38.253012 17384 maintenance_manager.cc:643] P ed45f7ed68e348ba8c41a1e1590b5678: FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4012,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:38.253582 17482 maintenance_manager.cc:419] P ed45f7ed68e348ba8c41a1e1590b5678: Scheduling MajorDeltaCompactionOp(eba70b9d14374222911601482567e612): perf score=1.000000
I20260812 06:19:38.432677 17384 maintenance_manager.cc:643] P ed45f7ed68e348ba8c41a1e1590b5678: MajorDeltaCompactionOp(eba70b9d14374222911601482567e612) complete. Timing: real 0.179s	user 0.130s	sys 0.045s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24856655,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":234,"lbm_read_time_us":10718,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27412,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:38.433522 17482 maintenance_manager.cc:419] P ed45f7ed68e348ba8c41a1e1590b5678: Scheduling FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612): perf score=14.095187
I20260812 06:19:38.477991 17384 maintenance_manager.cc:643] P ed45f7ed68e348ba8c41a1e1590b5678: FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612) complete. Timing: real 0.044s	user 0.030s	sys 0.005s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":16642,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:38.478524 17482 maintenance_manager.cc:419] P ed45f7ed68e348ba8c41a1e1590b5678: Scheduling FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612): perf score=2.188937
I20260812 06:19:38.488341 17384 maintenance_manager.cc:643] P ed45f7ed68e348ba8c41a1e1590b5678: FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3799,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:38.488862 17482 maintenance_manager.cc:419] P ed45f7ed68e348ba8c41a1e1590b5678: Scheduling FlushMRSOp(eba70b9d14374222911601482567e612): perf score=1.000000
I20260812 06:19:38.523072 17384 maintenance_manager.cc:643] P ed45f7ed68e348ba8c41a1e1590b5678: FlushMRSOp(eba70b9d14374222911601482567e612) complete. Timing: real 0.034s	user 0.028s	sys 0.005s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":48,"dirs.run_cpu_time_us":169,"dirs.run_wall_time_us":993,"drs_written":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4,"lbm_write_time_us":3129,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:19:38.523746 17482 maintenance_manager.cc:419] P ed45f7ed68e348ba8c41a1e1590b5678: Scheduling LogGCOp(eba70b9d14374222911601482567e612): free 112692380 bytes of WAL
I20260812 06:19:38.523973 17384 log_reader.cc:385] T eba70b9d14374222911601482567e612: removed 11 log segments from log reader
I20260812 06:19:38.524034 17384 log.cc:1079] T eba70b9d14374222911601482567e612 P ed45f7ed68e348ba8c41a1e1590b5678: Deleting log segment in path: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515571797997-16945-0/minicluster-data/ts-0-root/wals/eba70b9d14374222911601482567e612/wal-000000004 (ops 17-21)
I20260812 06:19:38.524080 17384 log.cc:1079] T eba70b9d14374222911601482567e612 P ed45f7ed68e348ba8c41a1e1590b5678: Deleting log segment in path: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515571797997-16945-0/minicluster-data/ts-0-root/wals/eba70b9d14374222911601482567e612/wal-000000005 (ops 22-26)
I20260812 06:19:38.524111 17384 log.cc:1079] T eba70b9d14374222911601482567e612 P ed45f7ed68e348ba8c41a1e1590b5678: Deleting log segment in path: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515571797997-16945-0/minicluster-data/ts-0-root/wals/eba70b9d14374222911601482567e612/wal-000000006 (ops 27-31)
I20260812 06:19:38.524132 17384 log.cc:1079] T eba70b9d14374222911601482567e612 P ed45f7ed68e348ba8c41a1e1590b5678: Deleting log segment in path: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515571797997-16945-0/minicluster-data/ts-0-root/wals/eba70b9d14374222911601482567e612/wal-000000007 (ops 32-36)
I20260812 06:19:38.524160 17384 log.cc:1079] T eba70b9d14374222911601482567e612 P ed45f7ed68e348ba8c41a1e1590b5678: Deleting log segment in path: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515571797997-16945-0/minicluster-data/ts-0-root/wals/eba70b9d14374222911601482567e612/wal-000000008 (ops 37-41)
I20260812 06:19:38.524191 17384 log.cc:1079] T eba70b9d14374222911601482567e612 P ed45f7ed68e348ba8c41a1e1590b5678: Deleting log segment in path: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515571797997-16945-0/minicluster-data/ts-0-root/wals/eba70b9d14374222911601482567e612/wal-000000009 (ops 42-46)
I20260812 06:19:38.524223 17384 log.cc:1079] T eba70b9d14374222911601482567e612 P ed45f7ed68e348ba8c41a1e1590b5678: Deleting log segment in path: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515571797997-16945-0/minicluster-data/ts-0-root/wals/eba70b9d14374222911601482567e612/wal-000000010 (ops 47-51)
I20260812 06:19:38.524252 17384 log.cc:1079] T eba70b9d14374222911601482567e612 P ed45f7ed68e348ba8c41a1e1590b5678: Deleting log segment in path: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515571797997-16945-0/minicluster-data/ts-0-root/wals/eba70b9d14374222911601482567e612/wal-000000011 (ops 52-56)
I20260812 06:19:38.524279 17384 log.cc:1079] T eba70b9d14374222911601482567e612 P ed45f7ed68e348ba8c41a1e1590b5678: Deleting log segment in path: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515571797997-16945-0/minicluster-data/ts-0-root/wals/eba70b9d14374222911601482567e612/wal-000000012 (ops 57-61)
I20260812 06:19:38.524307 17384 log.cc:1079] T eba70b9d14374222911601482567e612 P ed45f7ed68e348ba8c41a1e1590b5678: Deleting log segment in path: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515571797997-16945-0/minicluster-data/ts-0-root/wals/eba70b9d14374222911601482567e612/wal-000000013 (ops 62-66)
I20260812 06:19:38.524338 17384 log.cc:1079] T eba70b9d14374222911601482567e612 P ed45f7ed68e348ba8c41a1e1590b5678: Deleting log segment in path: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515571797997-16945-0/minicluster-data/ts-0-root/wals/eba70b9d14374222911601482567e612/wal-000000014 (ops 67-71)
I20260812 06:19:38.549453 17384 maintenance_manager.cc:643] P ed45f7ed68e348ba8c41a1e1590b5678: LogGCOp(eba70b9d14374222911601482567e612) complete. Timing: real 0.026s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:19:38.549860 17482 maintenance_manager.cc:419] P ed45f7ed68e348ba8c41a1e1590b5678: Scheduling FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612): perf score=3.181125
I20260812 06:19:38.570626 17384 maintenance_manager.cc:643] P ed45f7ed68e348ba8c41a1e1590b5678: FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612) complete. Timing: real 0.021s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4195,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:38.571118 17482 maintenance_manager.cc:419] P ed45f7ed68e348ba8c41a1e1590b5678: Scheduling FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612): perf score=2.188937
I20260812 06:19:38.580086 17384 maintenance_manager.cc:643] P ed45f7ed68e348ba8c41a1e1590b5678: FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612) complete. Timing: real 0.009s	user 0.001s	sys 0.006s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3280,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:38.580480 17482 maintenance_manager.cc:419] P ed45f7ed68e348ba8c41a1e1590b5678: Scheduling UndoDeltaBlockGCOp(eba70b9d14374222911601482567e612): 463 bytes on disk
I20260812 06:19:38.580832 17384 maintenance_manager.cc:643] P ed45f7ed68e348ba8c41a1e1590b5678: UndoDeltaBlockGCOp(eba70b9d14374222911601482567e612) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4}
I20260812 06:19:38.581228 17482 maintenance_manager.cc:419] P ed45f7ed68e348ba8c41a1e1590b5678: Scheduling MajorDeltaCompactionOp(eba70b9d14374222911601482567e612): perf score=1.000000
I20260812 06:19:38.800073 17384 maintenance_manager.cc:643] P ed45f7ed68e348ba8c41a1e1590b5678: MajorDeltaCompactionOp(eba70b9d14374222911601482567e612) complete. Timing: real 0.219s	user 0.159s	sys 0.055s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33061704,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1534,"lbm_read_time_us":14220,"lbm_reads_lt_1ms":774,"lbm_write_time_us":35070,"lbm_writes_lt_1ms":743,"mutex_wait_us":298,"peak_mem_usage":87969044,"reinsert_count":0,"thread_start_us":111,"threads_started":1,"update_count":3500}
I20260812 06:19:38.800933 17482 maintenance_manager.cc:419] P ed45f7ed68e348ba8c41a1e1590b5678: Scheduling FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612): perf score=18.063937
I20260812 06:19:38.868434 17384 maintenance_manager.cc:643] P ed45f7ed68e348ba8c41a1e1590b5678: FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612) complete. Timing: real 0.067s	user 0.031s	sys 0.020s Metrics: {"bytes_written":20512314,"delete_count":0,"lbm_write_time_us":24284,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:38.868888 17482 maintenance_manager.cc:419] P ed45f7ed68e348ba8c41a1e1590b5678: Scheduling FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612): perf score=2.188937
I20260812 06:19:38.880901 17384 maintenance_manager.cc:643] P ed45f7ed68e348ba8c41a1e1590b5678: FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612) complete. Timing: real 0.012s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4158,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:38.881572 17482 maintenance_manager.cc:419] P ed45f7ed68e348ba8c41a1e1590b5678: Scheduling MajorDeltaCompactionOp(eba70b9d14374222911601482567e612): perf score=1.000000
I20260812 06:19:39.073000 17384 maintenance_manager.cc:643] P ed45f7ed68e348ba8c41a1e1590b5678: MajorDeltaCompactionOp(eba70b9d14374222911601482567e612) complete. Timing: real 0.191s	user 0.120s	sys 0.071s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28959066,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":135,"lbm_read_time_us":13874,"lbm_reads_lt_1ms":672,"lbm_write_time_us":32236,"lbm_writes_lt_1ms":643,"mutex_wait_us":33,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":6400,"update_count":3000}
I20260812 06:19:39.073559 17482 maintenance_manager.cc:419] P ed45f7ed68e348ba8c41a1e1590b5678: Scheduling FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612): perf score=14.095187
I20260812 06:19:39.119179 17384 maintenance_manager.cc:643] P ed45f7ed68e348ba8c41a1e1590b5678: FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612) complete. Timing: real 0.045s	user 0.038s	sys 0.007s Metrics: {"bytes_written":16491949,"delete_count":0,"lbm_write_time_us":20054,"lbm_writes_lt_1ms":405,"reinsert_count":0,"update_count":2010}
I20260812 06:19:39.119675 17482 maintenance_manager.cc:419] P ed45f7ed68e348ba8c41a1e1590b5678: Scheduling FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612): perf score=2.188937
I20260812 06:19:39.130295 17384 maintenance_manager.cc:643] P ed45f7ed68e348ba8c41a1e1590b5678: FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4020609,"delete_count":0,"lbm_write_time_us":3958,"lbm_writes_lt_1ms":101,"reinsert_count":0,"update_count":490}
I20260812 06:19:39.130934 17482 maintenance_manager.cc:419] P ed45f7ed68e348ba8c41a1e1590b5678: Scheduling MajorDeltaCompactionOp(eba70b9d14374222911601482567e612): perf score=1.000000
I20260812 06:19:39.287004 17384 maintenance_manager.cc:643] P ed45f7ed68e348ba8c41a1e1590b5678: MajorDeltaCompactionOp(eba70b9d14374222911601482567e612) complete. Timing: real 0.156s	user 0.106s	sys 0.043s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24856651,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":966,"lbm_read_time_us":10602,"lbm_reads_lt_1ms":568,"lbm_write_time_us":24606,"lbm_writes_lt_1ms":543,"mutex_wait_us":274,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2500}
I20260812 06:19:39.288231 17482 maintenance_manager.cc:419] P ed45f7ed68e348ba8c41a1e1590b5678: Scheduling FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612): perf score=14.095187
I20260812 06:19:39.344389 17384 maintenance_manager.cc:643] P ed45f7ed68e348ba8c41a1e1590b5678: FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612) complete. Timing: real 0.055s	user 0.030s	sys 0.024s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22033,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:39.344928 17482 maintenance_manager.cc:419] P ed45f7ed68e348ba8c41a1e1590b5678: Scheduling FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612): perf score=2.188937
I20260812 06:19:39.354897 17384 maintenance_manager.cc:643] P ed45f7ed68e348ba8c41a1e1590b5678: FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612) complete. Timing: real 0.010s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3705,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:39.357419 17482 maintenance_manager.cc:419] P ed45f7ed68e348ba8c41a1e1590b5678: Scheduling MajorDeltaCompactionOp(eba70b9d14374222911601482567e612): perf score=1.000000
I20260812 06:19:39.515789 17384 maintenance_manager.cc:643] P ed45f7ed68e348ba8c41a1e1590b5678: MajorDeltaCompactionOp(eba70b9d14374222911601482567e612) complete. Timing: real 0.158s	user 0.107s	sys 0.047s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24856654,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1001,"lbm_read_time_us":11027,"lbm_reads_lt_1ms":572,"lbm_write_time_us":23625,"lbm_writes_lt_1ms":543,"mutex_wait_us":286,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":29568,"update_count":2500}
I20260812 06:19:39.516316 17482 maintenance_manager.cc:419] P ed45f7ed68e348ba8c41a1e1590b5678: Scheduling FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612): perf score=14.095187
I20260812 06:19:39.577287 17384 maintenance_manager.cc:643] P ed45f7ed68e348ba8c41a1e1590b5678: FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612) complete. Timing: real 0.061s	user 0.033s	sys 0.020s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20781,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:39.577824 17482 maintenance_manager.cc:419] P ed45f7ed68e348ba8c41a1e1590b5678: Scheduling FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612): perf score=2.188937
I20260812 06:19:39.588128 17384 maintenance_manager.cc:643] P ed45f7ed68e348ba8c41a1e1590b5678: FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612) complete. Timing: real 0.010s	user 0.000s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3976,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:39.588630 17482 maintenance_manager.cc:419] P ed45f7ed68e348ba8c41a1e1590b5678: Scheduling MajorDeltaCompactionOp(eba70b9d14374222911601482567e612): perf score=1.000000
I20260812 06:19:39.761979 17384 maintenance_manager.cc:643] P ed45f7ed68e348ba8c41a1e1590b5678: MajorDeltaCompactionOp(eba70b9d14374222911601482567e612) complete. Timing: real 0.173s	user 0.111s	sys 0.053s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24856655,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":168,"lbm_read_time_us":11455,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26863,"lbm_writes_lt_1ms":543,"mutex_wait_us":49,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10240,"update_count":2500}
I20260812 06:19:39.762507 17482 maintenance_manager.cc:419] P ed45f7ed68e348ba8c41a1e1590b5678: Scheduling FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612): perf score=14.095187
I20260812 06:19:39.812391 17384 maintenance_manager.cc:643] P ed45f7ed68e348ba8c41a1e1590b5678: FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612) complete. Timing: real 0.050s	user 0.018s	sys 0.027s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":16821,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:39.812932 17482 maintenance_manager.cc:419] P ed45f7ed68e348ba8c41a1e1590b5678: Scheduling FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612): perf score=2.188937
I20260812 06:19:39.827880 17384 maintenance_manager.cc:643] P ed45f7ed68e348ba8c41a1e1590b5678: FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612) complete. Timing: real 0.015s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5690,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:39.828361 17482 maintenance_manager.cc:419] P ed45f7ed68e348ba8c41a1e1590b5678: Scheduling FlushMRSOp(eba70b9d14374222911601482567e612): perf score=1.000000
I20260812 06:19:39.867209 17384 maintenance_manager.cc:643] P ed45f7ed68e348ba8c41a1e1590b5678: FlushMRSOp(eba70b9d14374222911601482567e612) complete. Timing: real 0.039s	user 0.026s	sys 0.000s Metrics: {"bytes_written":1152514,"cfile_init":1,"dirs.queue_time_us":43,"dirs.run_cpu_time_us":147,"dirs.run_wall_time_us":1262,"drs_written":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1443,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:39.867869 17482 maintenance_manager.cc:419] P ed45f7ed68e348ba8c41a1e1590b5678: Scheduling LogGCOp(eba70b9d14374222911601482567e612): free 112239321 bytes of WAL
I20260812 06:19:39.868081 17384 log_reader.cc:385] T eba70b9d14374222911601482567e612: removed 11 log segments from log reader
I20260812 06:19:39.868127 17384 log.cc:1079] T eba70b9d14374222911601482567e612 P ed45f7ed68e348ba8c41a1e1590b5678: Deleting log segment in path: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515571797997-16945-0/minicluster-data/ts-0-root/wals/eba70b9d14374222911601482567e612/wal-000000015 (ops 72-76)
I20260812 06:19:39.868156 17384 log.cc:1079] T eba70b9d14374222911601482567e612 P ed45f7ed68e348ba8c41a1e1590b5678: Deleting log segment in path: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515571797997-16945-0/minicluster-data/ts-0-root/wals/eba70b9d14374222911601482567e612/wal-000000016 (ops 77-80)
I20260812 06:19:39.868187 17384 log.cc:1079] T eba70b9d14374222911601482567e612 P ed45f7ed68e348ba8c41a1e1590b5678: Deleting log segment in path: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515571797997-16945-0/minicluster-data/ts-0-root/wals/eba70b9d14374222911601482567e612/wal-000000017 (ops 81-85)
I20260812 06:19:39.868220 17384 log.cc:1079] T eba70b9d14374222911601482567e612 P ed45f7ed68e348ba8c41a1e1590b5678: Deleting log segment in path: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515571797997-16945-0/minicluster-data/ts-0-root/wals/eba70b9d14374222911601482567e612/wal-000000018 (ops 86-90)
I20260812 06:19:39.868244 17384 log.cc:1079] T eba70b9d14374222911601482567e612 P ed45f7ed68e348ba8c41a1e1590b5678: Deleting log segment in path: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515571797997-16945-0/minicluster-data/ts-0-root/wals/eba70b9d14374222911601482567e612/wal-000000019 (ops 91-95)
I20260812 06:19:39.868275 17384 log.cc:1079] T eba70b9d14374222911601482567e612 P ed45f7ed68e348ba8c41a1e1590b5678: Deleting log segment in path: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515571797997-16945-0/minicluster-data/ts-0-root/wals/eba70b9d14374222911601482567e612/wal-000000020 (ops 96-100)
I20260812 06:19:39.868309 17384 log.cc:1079] T eba70b9d14374222911601482567e612 P ed45f7ed68e348ba8c41a1e1590b5678: Deleting log segment in path: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515571797997-16945-0/minicluster-data/ts-0-root/wals/eba70b9d14374222911601482567e612/wal-000000021 (ops 101-105)
I20260812 06:19:39.868341 17384 log.cc:1079] T eba70b9d14374222911601482567e612 P ed45f7ed68e348ba8c41a1e1590b5678: Deleting log segment in path: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515571797997-16945-0/minicluster-data/ts-0-root/wals/eba70b9d14374222911601482567e612/wal-000000022 (ops 106-110)
I20260812 06:19:39.868373 17384 log.cc:1079] T eba70b9d14374222911601482567e612 P ed45f7ed68e348ba8c41a1e1590b5678: Deleting log segment in path: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515571797997-16945-0/minicluster-data/ts-0-root/wals/eba70b9d14374222911601482567e612/wal-000000023 (ops 111-115)
I20260812 06:19:39.868405 17384 log.cc:1079] T eba70b9d14374222911601482567e612 P ed45f7ed68e348ba8c41a1e1590b5678: Deleting log segment in path: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515571797997-16945-0/minicluster-data/ts-0-root/wals/eba70b9d14374222911601482567e612/wal-000000024 (ops 116-120)
I20260812 06:19:39.868436 17384 log.cc:1079] T eba70b9d14374222911601482567e612 P ed45f7ed68e348ba8c41a1e1590b5678: Deleting log segment in path: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515571797997-16945-0/minicluster-data/ts-0-root/wals/eba70b9d14374222911601482567e612/wal-000000025 (ops 121-125)
I20260812 06:19:39.889567 17384 maintenance_manager.cc:643] P ed45f7ed68e348ba8c41a1e1590b5678: LogGCOp(eba70b9d14374222911601482567e612) complete. Timing: real 0.022s	user 0.000s	sys 0.019s Metrics: {}
I20260812 06:19:39.890626 17482 maintenance_manager.cc:419] P ed45f7ed68e348ba8c41a1e1590b5678: Scheduling FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612): perf score=3.181125
I20260812 06:19:39.914311 17384 maintenance_manager.cc:643] P ed45f7ed68e348ba8c41a1e1590b5678: FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612) complete. Timing: real 0.024s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4266756,"delete_count":0,"lbm_write_time_us":5517,"lbm_writes_lt_1ms":107,"reinsert_count":0,"update_count":520}
I20260812 06:19:39.914737 17482 maintenance_manager.cc:419] P ed45f7ed68e348ba8c41a1e1590b5678: Scheduling UndoDeltaBlockGCOp(eba70b9d14374222911601482567e612): 447 bytes on disk
I20260812 06:19:39.915133 17384 maintenance_manager.cc:643] P ed45f7ed68e348ba8c41a1e1590b5678: UndoDeltaBlockGCOp(eba70b9d14374222911601482567e612) 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:19:39.915599 17482 maintenance_manager.cc:419] P ed45f7ed68e348ba8c41a1e1590b5678: Scheduling FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612): perf score=2.188937
I20260812 06:19:39.924584 17384 maintenance_manager.cc:643] P ed45f7ed68e348ba8c41a1e1590b5678: FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612) complete. Timing: real 0.009s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3938559,"delete_count":0,"lbm_write_time_us":3308,"lbm_writes_lt_1ms":99,"reinsert_count":0,"update_count":480}
I20260812 06:19:39.925019 17482 maintenance_manager.cc:419] P ed45f7ed68e348ba8c41a1e1590b5678: Scheduling MajorDeltaCompactionOp(eba70b9d14374222911601482567e612): perf score=1.000000
I20260812 06:19:40.150153 17384 maintenance_manager.cc:643] P ed45f7ed68e348ba8c41a1e1590b5678: MajorDeltaCompactionOp(eba70b9d14374222911601482567e612) complete. Timing: real 0.225s	user 0.128s	sys 0.096s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33061712,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":386,"lbm_read_time_us":12892,"lbm_reads_lt_1ms":774,"lbm_write_time_us":40166,"lbm_writes_lt_1ms":743,"mutex_wait_us":25,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":60032,"thread_start_us":90,"threads_started":1,"update_count":3500}
I20260812 06:19:40.150770 17482 maintenance_manager.cc:419] P ed45f7ed68e348ba8c41a1e1590b5678: Scheduling FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612): perf score=18.063937
I20260812 06:19:40.210232 17384 maintenance_manager.cc:643] P ed45f7ed68e348ba8c41a1e1590b5678: FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612) complete. Timing: real 0.059s	user 0.025s	sys 0.020s Metrics: {"bytes_written":20512318,"delete_count":0,"lbm_write_time_us":21959,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:40.210708 17482 maintenance_manager.cc:419] P ed45f7ed68e348ba8c41a1e1590b5678: Scheduling FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612): perf score=2.188937
I20260812 06:19:40.225666 17384 maintenance_manager.cc:643] P ed45f7ed68e348ba8c41a1e1590b5678: FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5609,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:40.226346 17482 maintenance_manager.cc:419] P ed45f7ed68e348ba8c41a1e1590b5678: Scheduling MajorDeltaCompactionOp(eba70b9d14374222911601482567e612): perf score=1.000000
I20260812 06:19:40.413635 17384 maintenance_manager.cc:643] P ed45f7ed68e348ba8c41a1e1590b5678: MajorDeltaCompactionOp(eba70b9d14374222911601482567e612) complete. Timing: real 0.187s	user 0.147s	sys 0.040s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28959070,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":529,"lbm_read_time_us":13318,"lbm_reads_lt_1ms":672,"lbm_write_time_us":29580,"lbm_writes_lt_1ms":643,"mutex_wait_us":275,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2048,"update_count":3000}
I20260812 06:19:40.414127 17482 maintenance_manager.cc:419] P ed45f7ed68e348ba8c41a1e1590b5678: Scheduling FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612): perf score=14.095187
I20260812 06:19:40.462328 17384 maintenance_manager.cc:643] P ed45f7ed68e348ba8c41a1e1590b5678: FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612) complete. Timing: real 0.048s	user 0.017s	sys 0.028s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":20718,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:40.462952 17482 maintenance_manager.cc:419] P ed45f7ed68e348ba8c41a1e1590b5678: Scheduling FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612): perf score=2.188937
I20260812 06:19:40.488600 17384 maintenance_manager.cc:643] P ed45f7ed68e348ba8c41a1e1590b5678: FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612) complete. Timing: real 0.025s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5588,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:40.489077 17482 maintenance_manager.cc:419] P ed45f7ed68e348ba8c41a1e1590b5678: Scheduling FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612): perf score=2.188937
I20260812 06:19:40.503114 17384 maintenance_manager.cc:643] P ed45f7ed68e348ba8c41a1e1590b5678: FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612) complete. Timing: real 0.014s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5367,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:40.503556 17482 maintenance_manager.cc:419] P ed45f7ed68e348ba8c41a1e1590b5678: Scheduling MajorDeltaCompactionOp(eba70b9d14374222911601482567e612): perf score=1.000000
I20260812 06:19:40.689718 17384 maintenance_manager.cc:643] P ed45f7ed68e348ba8c41a1e1590b5678: MajorDeltaCompactionOp(eba70b9d14374222911601482567e612) complete. Timing: real 0.186s	user 0.128s	sys 0.055s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28959187,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":594,"lbm_read_time_us":12307,"lbm_reads_lt_1ms":673,"lbm_write_time_us":29533,"lbm_writes_lt_1ms":643,"mutex_wait_us":61,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":17664,"update_count":3000}
I20260812 06:19:40.690430 17482 maintenance_manager.cc:419] P ed45f7ed68e348ba8c41a1e1590b5678: Scheduling FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612): perf score=16.079562
I20260812 06:19:40.735185 17384 maintenance_manager.cc:643] P ed45f7ed68e348ba8c41a1e1590b5678: FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612) complete. Timing: real 0.045s	user 0.025s	sys 0.019s Metrics: {"bytes_written":17681653,"delete_count":0,"lbm_write_time_us":19500,"lbm_writes_lt_1ms":434,"reinsert_count":0,"update_count":2155}
I20260812 06:19:40.735772 17482 maintenance_manager.cc:419] P ed45f7ed68e348ba8c41a1e1590b5678: Scheduling FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612): perf score=2.188937
I20260812 06:19:40.753479 17384 maintenance_manager.cc:643] P ed45f7ed68e348ba8c41a1e1590b5678: FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612) complete. Timing: real 0.017s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3241134,"delete_count":0,"lbm_write_time_us":3616,"lbm_writes_lt_1ms":82,"reinsert_count":0,"update_count":395}
I20260812 06:19:40.753912 17482 maintenance_manager.cc:419] P ed45f7ed68e348ba8c41a1e1590b5678: Scheduling FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612): perf score=2.188937
I20260812 06:19:40.762966 17384 maintenance_manager.cc:643] P ed45f7ed68e348ba8c41a1e1590b5678: FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612) complete. Timing: real 0.009s	user 0.007s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3393,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:40.763367 17482 maintenance_manager.cc:419] P ed45f7ed68e348ba8c41a1e1590b5678: Scheduling MajorDeltaCompactionOp(eba70b9d14374222911601482567e612): perf score=1.000000
I20260812 06:19:40.960022 17384 maintenance_manager.cc:643] P ed45f7ed68e348ba8c41a1e1590b5678: MajorDeltaCompactionOp(eba70b9d14374222911601482567e612) complete. Timing: real 0.197s	user 0.127s	sys 0.069s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28959157,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":291,"lbm_read_time_us":13787,"lbm_reads_lt_1ms":673,"lbm_write_time_us":31401,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":8064,"update_count":3000}
I20260812 06:19:40.960601 17482 maintenance_manager.cc:419] P ed45f7ed68e348ba8c41a1e1590b5678: Scheduling FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612): perf score=14.095187
I20260812 06:19:41.003470 17384 maintenance_manager.cc:643] P ed45f7ed68e348ba8c41a1e1590b5678: FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612) complete. Timing: real 0.043s	user 0.026s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19147,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:41.004616 17482 maintenance_manager.cc:419] P ed45f7ed68e348ba8c41a1e1590b5678: Scheduling MajorDeltaCompactionOp(eba70b9d14374222911601482567e612): perf score=1.000000
I20260812 06:19:41.156379 17384 maintenance_manager.cc:643] P ed45f7ed68e348ba8c41a1e1590b5678: MajorDeltaCompactionOp(eba70b9d14374222911601482567e612) complete. Timing: real 0.152s	user 0.110s	sys 0.036s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20754122,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":307,"lbm_read_time_us":9763,"lbm_reads_lt_1ms":463,"lbm_write_time_us":23074,"lbm_writes_lt_1ms":443,"mutex_wait_us":63,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:41.156926 17482 maintenance_manager.cc:419] P ed45f7ed68e348ba8c41a1e1590b5678: Scheduling FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612): perf score=14.095187
I20260812 06:19:41.198376 17384 maintenance_manager.cc:643] P ed45f7ed68e348ba8c41a1e1590b5678: FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612) complete. Timing: real 0.041s	user 0.032s	sys 0.003s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":16419,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:41.198904 17482 maintenance_manager.cc:419] P ed45f7ed68e348ba8c41a1e1590b5678: Scheduling FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612): perf score=2.188937
I20260812 06:19:41.213981 17384 maintenance_manager.cc:643] P ed45f7ed68e348ba8c41a1e1590b5678: FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612) complete. Timing: real 0.015s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5765,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:41.214643 17482 maintenance_manager.cc:419] P ed45f7ed68e348ba8c41a1e1590b5678: Scheduling FlushMRSOp(eba70b9d14374222911601482567e612): perf score=1.000000
I20260812 06:19:41.246392 17384 maintenance_manager.cc:643] P ed45f7ed68e348ba8c41a1e1590b5678: FlushMRSOp(eba70b9d14374222911601482567e612) complete. Timing: real 0.032s	user 0.022s	sys 0.003s Metrics: {"bytes_written":1193505,"cfile_init":1,"dirs.queue_time_us":37,"dirs.run_cpu_time_us":159,"dirs.run_wall_time_us":1258,"drs_written":1,"lbm_read_time_us":35,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1536,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:19:41.247074 17482 maintenance_manager.cc:419] P ed45f7ed68e348ba8c41a1e1590b5678: Scheduling LogGCOp(eba70b9d14374222911601482567e612): free 128414668 bytes of WAL
I20260812 06:19:41.247291 17384 log_reader.cc:385] T eba70b9d14374222911601482567e612: removed 13 log segments from log reader
I20260812 06:19:41.247354 17384 log.cc:1079] T eba70b9d14374222911601482567e612 P ed45f7ed68e348ba8c41a1e1590b5678: Deleting log segment in path: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515571797997-16945-0/minicluster-data/ts-0-root/wals/eba70b9d14374222911601482567e612/wal-000000026 (ops 126-130)
I20260812 06:19:41.247399 17384 log.cc:1079] T eba70b9d14374222911601482567e612 P ed45f7ed68e348ba8c41a1e1590b5678: Deleting log segment in path: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515571797997-16945-0/minicluster-data/ts-0-root/wals/eba70b9d14374222911601482567e612/wal-000000027 (ops 131-134)
I20260812 06:19:41.247429 17384 log.cc:1079] T eba70b9d14374222911601482567e612 P ed45f7ed68e348ba8c41a1e1590b5678: Deleting log segment in path: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515571797997-16945-0/minicluster-data/ts-0-root/wals/eba70b9d14374222911601482567e612/wal-000000028 (ops 135-139)
I20260812 06:19:41.247453 17384 log.cc:1079] T eba70b9d14374222911601482567e612 P ed45f7ed68e348ba8c41a1e1590b5678: Deleting log segment in path: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515571797997-16945-0/minicluster-data/ts-0-root/wals/eba70b9d14374222911601482567e612/wal-000000029 (ops 140-144)
I20260812 06:19:41.247485 17384 log.cc:1079] T eba70b9d14374222911601482567e612 P ed45f7ed68e348ba8c41a1e1590b5678: Deleting log segment in path: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515571797997-16945-0/minicluster-data/ts-0-root/wals/eba70b9d14374222911601482567e612/wal-000000030 (ops 145-148)
I20260812 06:19:41.247514 17384 log.cc:1079] T eba70b9d14374222911601482567e612 P ed45f7ed68e348ba8c41a1e1590b5678: Deleting log segment in path: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515571797997-16945-0/minicluster-data/ts-0-root/wals/eba70b9d14374222911601482567e612/wal-000000031 (ops 149-153)
I20260812 06:19:41.247539 17384 log.cc:1079] T eba70b9d14374222911601482567e612 P ed45f7ed68e348ba8c41a1e1590b5678: Deleting log segment in path: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515571797997-16945-0/minicluster-data/ts-0-root/wals/eba70b9d14374222911601482567e612/wal-000000032 (ops 154-158)
I20260812 06:19:41.247563 17384 log.cc:1079] T eba70b9d14374222911601482567e612 P ed45f7ed68e348ba8c41a1e1590b5678: Deleting log segment in path: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515571797997-16945-0/minicluster-data/ts-0-root/wals/eba70b9d14374222911601482567e612/wal-000000033 (ops 159-163)
I20260812 06:19:41.247592 17384 log.cc:1079] T eba70b9d14374222911601482567e612 P ed45f7ed68e348ba8c41a1e1590b5678: Deleting log segment in path: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515571797997-16945-0/minicluster-data/ts-0-root/wals/eba70b9d14374222911601482567e612/wal-000000034 (ops 164-168)
I20260812 06:19:41.247624 17384 log.cc:1079] T eba70b9d14374222911601482567e612 P ed45f7ed68e348ba8c41a1e1590b5678: Deleting log segment in path: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515571797997-16945-0/minicluster-data/ts-0-root/wals/eba70b9d14374222911601482567e612/wal-000000035 (ops 169-172)
I20260812 06:19:41.247653 17384 log.cc:1079] T eba70b9d14374222911601482567e612 P ed45f7ed68e348ba8c41a1e1590b5678: Deleting log segment in path: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515571797997-16945-0/minicluster-data/ts-0-root/wals/eba70b9d14374222911601482567e612/wal-000000036 (ops 173-177)
I20260812 06:19:41.247678 17384 log.cc:1079] T eba70b9d14374222911601482567e612 P ed45f7ed68e348ba8c41a1e1590b5678: Deleting log segment in path: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515571797997-16945-0/minicluster-data/ts-0-root/wals/eba70b9d14374222911601482567e612/wal-000000037 (ops 178-182)
I20260812 06:19:41.247704 17384 log.cc:1079] T eba70b9d14374222911601482567e612 P ed45f7ed68e348ba8c41a1e1590b5678: Deleting log segment in path: /tmp/dist-test-taskcoNc8V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515571797997-16945-0/minicluster-data/ts-0-root/wals/eba70b9d14374222911601482567e612/wal-000000038 (ops 183-186)
I20260812 06:19:41.273779 17384 maintenance_manager.cc:643] P ed45f7ed68e348ba8c41a1e1590b5678: LogGCOp(eba70b9d14374222911601482567e612) complete. Timing: real 0.027s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:19:41.274161 17482 maintenance_manager.cc:419] P ed45f7ed68e348ba8c41a1e1590b5678: Scheduling FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612): perf score=3.181125
I20260812 06:19:41.294212 17384 maintenance_manager.cc:643] P ed45f7ed68e348ba8c41a1e1590b5678: FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612) complete. Timing: real 0.020s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4512899,"delete_count":0,"lbm_write_time_us":4088,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:41.294677 17482 maintenance_manager.cc:419] P ed45f7ed68e348ba8c41a1e1590b5678: Scheduling FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612): perf score=2.188937
I20260812 06:19:41.303864 17384 maintenance_manager.cc:643] P ed45f7ed68e348ba8c41a1e1590b5678: FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3357,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:41.304334 17482 maintenance_manager.cc:419] P ed45f7ed68e348ba8c41a1e1590b5678: Scheduling MajorDeltaCompactionOp(eba70b9d14374222911601482567e612): perf score=1.000000
I20260812 06:19:41.526019 17384 maintenance_manager.cc:643] P ed45f7ed68e348ba8c41a1e1590b5678: MajorDeltaCompactionOp(eba70b9d14374222911601482567e612) complete. Timing: real 0.221s	user 0.139s	sys 0.071s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33061700,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":758,"lbm_read_time_us":14397,"lbm_reads_lt_1ms":774,"lbm_write_time_us":33423,"lbm_writes_lt_1ms":743,"mutex_wait_us":54,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":1408,"thread_start_us":92,"threads_started":1,"update_count":3500}
I20260812 06:19:41.526654 17482 maintenance_manager.cc:419] P ed45f7ed68e348ba8c41a1e1590b5678: Scheduling FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612): perf score=18.063937
I20260812 06:19:41.580943 17384 maintenance_manager.cc:643] P ed45f7ed68e348ba8c41a1e1590b5678: FlushDeltaMemStoresOp(eba70b9d14374222911601482567e612) complete. Timing: real 0.054s	user 0.035s	sys 0.008s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":20144,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:41.581624 17482 maintenance_manager.cc:419] P ed45f7ed68e348ba8c41a1e1590b5678: Scheduling UndoDeltaBlockGCOp(eba70b9d14374222911601482567e612): 462 bytes on disk
I20260812 06:19:41.582149 17384 maintenance_manager.cc:643] P ed45f7ed68e348ba8c41a1e1590b5678: UndoDeltaBlockGCOp(eba70b9d14374222911601482567e612) 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:19:41.582913 17482 maintenance_manager.cc:419] P ed45f7ed68e348ba8c41a1e1590b5678: Scheduling MajorDeltaCompactionOp(eba70b9d14374222911601482567e612): perf score=1.000000
I20260812 06:19:41.591967 16945 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.654s	user 1.718s	sys 0.167s
I20260812 06:19:41.655988 16945 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.064s	user 0.001s	sys 0.000s
I20260812 06:19:41.656456 16945 tablet_server.cc:179] TabletServer@127.16.140.65:0 shutting down...
I20260812 06:19:41.718006 17384 maintenance_manager.cc:643] P ed45f7ed68e348ba8c41a1e1590b5678: MajorDeltaCompactionOp(eba70b9d14374222911601482567e612) complete. Timing: real 0.135s	user 0.086s	sys 0.049s Metrics: {"cfile_cache_miss":531,"cfile_cache_miss_bytes":24856536,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":900,"lbm_read_time_us":11024,"lbm_reads_lt_1ms":559,"lbm_write_time_us":21933,"lbm_writes_lt_1ms":543,"mutex_wait_us":314,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":34432,"update_count":2500}
I20260812 06:19:41.718566 16945 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:41.718830 16945 tablet_replica.cc:333] T eba70b9d14374222911601482567e612 P ed45f7ed68e348ba8c41a1e1590b5678: stopping tablet replica
I20260812 06:19:41.718971 16945 raft_consensus.cc:2243] T eba70b9d14374222911601482567e612 P ed45f7ed68e348ba8c41a1e1590b5678 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:41.719120 16945 raft_consensus.cc:2272] T eba70b9d14374222911601482567e612 P ed45f7ed68e348ba8c41a1e1590b5678 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:41.735102 16945 tablet_server.cc:196] TabletServer@127.16.140.65:0 shutdown complete.
I20260812 06:19:41.763010 16945 master.cc:562] Master@127.16.140.126:44679 shutting down...
I20260812 06:19:41.765910 16945 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 3241aff3f6474320a0ac0469469ca3ea [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:41.766081 16945 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 3241aff3f6474320a0ac0469469ca3ea [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:41.766151 16945 tablet_replica.cc:333] T 00000000000000000000000000000000 P 3241aff3f6474320a0ac0469469ca3ea: stopping tablet replica
I20260812 06:19:41.778095 16945 master.cc:584] Master@127.16.140.126:44679 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5080 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10038 ms total)

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