[==========] 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:17:38.682142 13662 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.13.87.190:35689
I20260812 06:17:38.683079 13662 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:17:38.683653 13662 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:17:38.689656 13662 server_base.cc:1061] running on GCE node
W20260812 06:17:38.689692 13670 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:17:38.689852 13668 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:38.690119 13667 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:17:38.690580 13662 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:38.690688 13662 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:17:38.690732 13662 hybrid_clock.cc:648] HybridClock initialized: now 1786515458690728 us; error 0 us; skew 500 ppm
I20260812 06:17:38.692359 13662 webserver.cc:533] Webserver started at http://127.13.87.190:34473/ using document root <none> and password file <none>
I20260812 06:17:38.692896 13662 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:38.692955 13662 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:38.693161 13662 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:38.694737 13662 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458671825-13662-0/minicluster-data/master-0-root/instance:
uuid: "ae80b58b74fd4ed7b2f70c217ce71b4b"
format_stamp: "Formatted at 2026-08-12 06:17:38 on dist-test-slave-f7th"
I20260812 06:17:38.698151 13662 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.001s	sys 0.004s
I20260812 06:17:38.700567 13675 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:17:38.701747 13662 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.000s	sys 0.003s
I20260812 06:17:38.701853 13662 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458671825-13662-0/minicluster-data/master-0-root
uuid: "ae80b58b74fd4ed7b2f70c217ce71b4b"
format_stamp: "Formatted at 2026-08-12 06:17:38 on dist-test-slave-f7th"
I20260812 06:17:38.701949 13662 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458671825-13662-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458671825-13662-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458671825-13662-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:17:38.715662 13662 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:38.716279 13662 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:17:38.716427 13662 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:38.724058 13662 rpc_server.cc:307] RPC server started. Bound to: 127.13.87.190:35689
I20260812 06:17:38.724074 13727 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.13.87.190:35689 every 8 connection(s)
I20260812 06:17:38.726286 13728 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:17:38.731753 13728 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P ae80b58b74fd4ed7b2f70c217ce71b4b: Bootstrap starting.
I20260812 06:17:38.734081 13728 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P ae80b58b74fd4ed7b2f70c217ce71b4b: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:38.734987 13728 log.cc:826] T 00000000000000000000000000000000 P ae80b58b74fd4ed7b2f70c217ce71b4b: Log is configured to *not* fsync() on all Append() calls
I20260812 06:17:38.736850 13728 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P ae80b58b74fd4ed7b2f70c217ce71b4b: No bootstrap required, opened a new log
I20260812 06:17:38.739868 13728 raft_consensus.cc:359] T 00000000000000000000000000000000 P ae80b58b74fd4ed7b2f70c217ce71b4b [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ae80b58b74fd4ed7b2f70c217ce71b4b" member_type: VOTER }
I20260812 06:17:38.740047 13728 raft_consensus.cc:385] T 00000000000000000000000000000000 P ae80b58b74fd4ed7b2f70c217ce71b4b [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:38.740114 13728 raft_consensus.cc:740] T 00000000000000000000000000000000 P ae80b58b74fd4ed7b2f70c217ce71b4b [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: ae80b58b74fd4ed7b2f70c217ce71b4b, State: Initialized, Role: FOLLOWER
I20260812 06:17:38.740741 13728 consensus_queue.cc:260] T 00000000000000000000000000000000 P ae80b58b74fd4ed7b2f70c217ce71b4b [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: "ae80b58b74fd4ed7b2f70c217ce71b4b" member_type: VOTER }
I20260812 06:17:38.740893 13728 raft_consensus.cc:399] T 00000000000000000000000000000000 P ae80b58b74fd4ed7b2f70c217ce71b4b [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:38.740958 13728 raft_consensus.cc:493] T 00000000000000000000000000000000 P ae80b58b74fd4ed7b2f70c217ce71b4b [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:38.741086 13728 raft_consensus.cc:3060] T 00000000000000000000000000000000 P ae80b58b74fd4ed7b2f70c217ce71b4b [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:38.741856 13728 raft_consensus.cc:515] T 00000000000000000000000000000000 P ae80b58b74fd4ed7b2f70c217ce71b4b [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ae80b58b74fd4ed7b2f70c217ce71b4b" member_type: VOTER }
I20260812 06:17:38.742296 13728 leader_election.cc:304] T 00000000000000000000000000000000 P ae80b58b74fd4ed7b2f70c217ce71b4b [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: ae80b58b74fd4ed7b2f70c217ce71b4b; no voters: 
I20260812 06:17:38.742604 13728 leader_election.cc:290] T 00000000000000000000000000000000 P ae80b58b74fd4ed7b2f70c217ce71b4b [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:38.742748 13731 raft_consensus.cc:2804] T 00000000000000000000000000000000 P ae80b58b74fd4ed7b2f70c217ce71b4b [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:38.742971 13731 raft_consensus.cc:697] T 00000000000000000000000000000000 P ae80b58b74fd4ed7b2f70c217ce71b4b [term 1 LEADER]: Becoming Leader. State: Replica: ae80b58b74fd4ed7b2f70c217ce71b4b, State: Running, Role: LEADER
I20260812 06:17:38.743419 13731 consensus_queue.cc:237] T 00000000000000000000000000000000 P ae80b58b74fd4ed7b2f70c217ce71b4b [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: "ae80b58b74fd4ed7b2f70c217ce71b4b" member_type: VOTER }
I20260812 06:17:38.743577 13728 sys_catalog.cc:565] T 00000000000000000000000000000000 P ae80b58b74fd4ed7b2f70c217ce71b4b [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:38.745529 13732 sys_catalog.cc:455] T 00000000000000000000000000000000 P ae80b58b74fd4ed7b2f70c217ce71b4b [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "ae80b58b74fd4ed7b2f70c217ce71b4b" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ae80b58b74fd4ed7b2f70c217ce71b4b" member_type: VOTER } }
I20260812 06:17:38.745543 13733 sys_catalog.cc:455] T 00000000000000000000000000000000 P ae80b58b74fd4ed7b2f70c217ce71b4b [sys.catalog]: SysCatalogTable state changed. Reason: New leader ae80b58b74fd4ed7b2f70c217ce71b4b. Latest consensus state: current_term: 1 leader_uuid: "ae80b58b74fd4ed7b2f70c217ce71b4b" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ae80b58b74fd4ed7b2f70c217ce71b4b" member_type: VOTER } }
I20260812 06:17:38.745656 13732 sys_catalog.cc:458] T 00000000000000000000000000000000 P ae80b58b74fd4ed7b2f70c217ce71b4b [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:38.745707 13733 sys_catalog.cc:458] T 00000000000000000000000000000000 P ae80b58b74fd4ed7b2f70c217ce71b4b [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:38.745735 13662 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:38.746032 13746 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:38.748615 13746 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:38.753845 13746 catalog_manager.cc:1383] Generated new cluster ID: 24cce240d1c74a6cbbd1a02e68730e57
I20260812 06:17:38.753901 13746 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:38.771204 13746 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:38.772473 13746 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:38.783752 13746 catalog_manager.cc:6092] T 00000000000000000000000000000000 P ae80b58b74fd4ed7b2f70c217ce71b4b: Generated new TSK 0
I20260812 06:17:38.784560 13746 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:38.810735 13662 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:38.813939 13751 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:38.813980 13750 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:17:38.814260 13662 server_base.cc:1061] running on GCE node
W20260812 06:17:38.814399 13753 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:17:38.814620 13662 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:38.814678 13662 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:17:38.814741 13662 hybrid_clock.cc:648] HybridClock initialized: now 1786515458814740 us; error 0 us; skew 500 ppm
I20260812 06:17:38.815743 13662 webserver.cc:533] Webserver started at http://127.13.87.129:44529/ using document root <none> and password file <none>
I20260812 06:17:38.815905 13662 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:38.815959 13662 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:38.816035 13662 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:38.816488 13662 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458671825-13662-0/minicluster-data/ts-0-root/instance:
uuid: "d1cefeb13ffa40579a89e6a1b33a0950"
format_stamp: "Formatted at 2026-08-12 06:17:38 on dist-test-slave-f7th"
I20260812 06:17:38.818312 13662 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:38.819406 13758 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:17:38.819679 13662 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:38.819757 13662 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458671825-13662-0/minicluster-data/ts-0-root
uuid: "d1cefeb13ffa40579a89e6a1b33a0950"
format_stamp: "Formatted at 2026-08-12 06:17:38 on dist-test-slave-f7th"
I20260812 06:17:38.819824 13662 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458671825-13662-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458671825-13662-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458671825-13662-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:17:38.832334 13662 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:38.832934 13662 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:38.833503 13662 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:38.834523 13662 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:38.834589 13662 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:38.834645 13662 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:38.834720 13662 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:38.841352 13662 rpc_server.cc:307] RPC server started. Bound to: 127.13.87.129:36939
I20260812 06:17:38.841634 13821 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.13.87.129:36939 every 8 connection(s)
I20260812 06:17:38.853097 13822 heartbeater.cc:344] Connected to a master server at 127.13.87.190:35689
I20260812 06:17:38.853331 13822 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:38.853798 13822 heartbeater.cc:507] Master 127.13.87.190:35689 requested a full tablet report, sending...
I20260812 06:17:38.855108 13692 ts_manager.cc:194] Registered new tserver with Master: d1cefeb13ffa40579a89e6a1b33a0950 (127.13.87.129:36939)
I20260812 06:17:38.855814 13662 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.013637553s
I20260812 06:17:38.856463 13692 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:34148
I20260812 06:17:38.866108 13692 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:34162:
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:17:38.880962 13786 tablet_service.cc:1511] Processing CreateTablet for tablet 5afacfdac0284281bbf4484aa7a756fa (DEFAULT_TABLE table=heavy-update-compaction-test [id=4f4070def03a4b4fbcd5d41e7aef4560]), partition=
I20260812 06:17:38.881428 13786 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 5afacfdac0284281bbf4484aa7a756fa. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:38.883875 13835 tablet_bootstrap.cc:492] T 5afacfdac0284281bbf4484aa7a756fa P d1cefeb13ffa40579a89e6a1b33a0950: Bootstrap starting.
I20260812 06:17:38.884724 13835 tablet_bootstrap.cc:654] T 5afacfdac0284281bbf4484aa7a756fa P d1cefeb13ffa40579a89e6a1b33a0950: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:38.885883 13835 tablet_bootstrap.cc:492] T 5afacfdac0284281bbf4484aa7a756fa P d1cefeb13ffa40579a89e6a1b33a0950: No bootstrap required, opened a new log
I20260812 06:17:38.885996 13835 ts_tablet_manager.cc:1403] T 5afacfdac0284281bbf4484aa7a756fa P d1cefeb13ffa40579a89e6a1b33a0950: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:38.886456 13835 raft_consensus.cc:359] T 5afacfdac0284281bbf4484aa7a756fa P d1cefeb13ffa40579a89e6a1b33a0950 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d1cefeb13ffa40579a89e6a1b33a0950" member_type: VOTER last_known_addr { host: "127.13.87.129" port: 36939 } }
I20260812 06:17:38.886572 13835 raft_consensus.cc:385] T 5afacfdac0284281bbf4484aa7a756fa P d1cefeb13ffa40579a89e6a1b33a0950 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:38.886601 13835 raft_consensus.cc:740] T 5afacfdac0284281bbf4484aa7a756fa P d1cefeb13ffa40579a89e6a1b33a0950 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: d1cefeb13ffa40579a89e6a1b33a0950, State: Initialized, Role: FOLLOWER
I20260812 06:17:38.886756 13835 consensus_queue.cc:260] T 5afacfdac0284281bbf4484aa7a756fa P d1cefeb13ffa40579a89e6a1b33a0950 [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: "d1cefeb13ffa40579a89e6a1b33a0950" member_type: VOTER last_known_addr { host: "127.13.87.129" port: 36939 } }
I20260812 06:17:38.886910 13835 raft_consensus.cc:399] T 5afacfdac0284281bbf4484aa7a756fa P d1cefeb13ffa40579a89e6a1b33a0950 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:38.887010 13835 raft_consensus.cc:493] T 5afacfdac0284281bbf4484aa7a756fa P d1cefeb13ffa40579a89e6a1b33a0950 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:38.887099 13835 raft_consensus.cc:3060] T 5afacfdac0284281bbf4484aa7a756fa P d1cefeb13ffa40579a89e6a1b33a0950 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:38.888065 13835 raft_consensus.cc:515] T 5afacfdac0284281bbf4484aa7a756fa P d1cefeb13ffa40579a89e6a1b33a0950 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d1cefeb13ffa40579a89e6a1b33a0950" member_type: VOTER last_known_addr { host: "127.13.87.129" port: 36939 } }
I20260812 06:17:38.888216 13835 leader_election.cc:304] T 5afacfdac0284281bbf4484aa7a756fa P d1cefeb13ffa40579a89e6a1b33a0950 [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: d1cefeb13ffa40579a89e6a1b33a0950; no voters: 
I20260812 06:17:38.888408 13835 leader_election.cc:290] T 5afacfdac0284281bbf4484aa7a756fa P d1cefeb13ffa40579a89e6a1b33a0950 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:38.888521 13837 raft_consensus.cc:2804] T 5afacfdac0284281bbf4484aa7a756fa P d1cefeb13ffa40579a89e6a1b33a0950 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:38.888706 13837 raft_consensus.cc:697] T 5afacfdac0284281bbf4484aa7a756fa P d1cefeb13ffa40579a89e6a1b33a0950 [term 1 LEADER]: Becoming Leader. State: Replica: d1cefeb13ffa40579a89e6a1b33a0950, State: Running, Role: LEADER
I20260812 06:17:38.888715 13835 ts_tablet_manager.cc:1434] T 5afacfdac0284281bbf4484aa7a756fa P d1cefeb13ffa40579a89e6a1b33a0950: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:17:38.888944 13837 consensus_queue.cc:237] T 5afacfdac0284281bbf4484aa7a756fa P d1cefeb13ffa40579a89e6a1b33a0950 [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: "d1cefeb13ffa40579a89e6a1b33a0950" member_type: VOTER last_known_addr { host: "127.13.87.129" port: 36939 } }
I20260812 06:17:38.889088 13822 heartbeater.cc:499] Master 127.13.87.190:35689 was elected leader, sending a full tablet report...
I20260812 06:17:38.891713 13692 catalog_manager.cc:5719] T 5afacfdac0284281bbf4484aa7a756fa P d1cefeb13ffa40579a89e6a1b33a0950 reported cstate change: term changed from 0 to 1, leader changed from <none> to d1cefeb13ffa40579a89e6a1b33a0950 (127.13.87.129). New cstate: current_term: 1 leader_uuid: "d1cefeb13ffa40579a89e6a1b33a0950" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d1cefeb13ffa40579a89e6a1b33a0950" member_type: VOTER last_known_addr { host: "127.13.87.129" port: 36939 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:38.965009 13662 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.064s	user 0.016s	sys 0.017s
I20260812 06:17:39.092743 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling FlushMRSOp(5afacfdac0284281bbf4484aa7a756fa): perf score=15.086190
I20260812 06:17:39.273993 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: FlushMRSOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.181s	user 0.130s	sys 0.034s Metrics: {"bytes_written":11897249,"cfile_init":1,"compiler_manager_pool.queue_time_us":231,"delete_count":0,"dirs.queue_time_us":41,"dirs.run_cpu_time_us":187,"dirs.run_wall_time_us":765,"drs_written":1,"lbm_read_time_us":81,"lbm_reads_lt_1ms":4,"lbm_write_time_us":43591,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":655,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":121,"threads_started":1,"update_count":1450}
I20260812 06:17:39.275446 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling LogGCOp(5afacfdac0284281bbf4484aa7a756fa): free 20743880 bytes of WAL
I20260812 06:17:39.293644 13763 log_reader.cc:385] T 5afacfdac0284281bbf4484aa7a756fa: removed 2 log segments from log reader
I20260812 06:17:39.293841 13763 log.cc:1079] T 5afacfdac0284281bbf4484aa7a756fa P d1cefeb13ffa40579a89e6a1b33a0950: Deleting log segment in path: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458671825-13662-0/minicluster-data/ts-0-root/wals/5afacfdac0284281bbf4484aa7a756fa/wal-000000001 (ops 1-6)
I20260812 06:17:39.293963 13763 log.cc:1079] T 5afacfdac0284281bbf4484aa7a756fa P d1cefeb13ffa40579a89e6a1b33a0950: Deleting log segment in path: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458671825-13662-0/minicluster-data/ts-0-root/wals/5afacfdac0284281bbf4484aa7a756fa/wal-000000002 (ops 7-11)
I20260812 06:17:39.298717 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: LogGCOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.005s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:17:39.300659 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa): perf score=5.165500
I20260812 06:17:39.347831 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.047s	user 0.008s	sys 0.016s Metrics: {"bytes_written":7425618,"delete_count":0,"lbm_write_time_us":21949,"lbm_writes_10-100_ms":1,"lbm_writes_lt_1ms":183,"reinsert_count":0,"update_count":905}
I20260812 06:17:39.348662 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling UndoDeltaBlockGCOp(5afacfdac0284281bbf4484aa7a756fa): 12719215 bytes on disk
I20260812 06:17:39.349491 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: UndoDeltaBlockGCOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":81,"lbm_reads_lt_1ms":4}
I20260812 06:17:39.350049 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa): perf score=1.196750
I20260812 06:17:39.362913 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":3077038,"delete_count":0,"lbm_write_time_us":4355,"lbm_writes_lt_1ms":78,"reinsert_count":0,"update_count":375}
I20260812 06:17:39.363341 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa): perf score=1.000000
I20260812 06:17:39.369203 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.006s	user 0.004s	sys 0.000s Metrics: {"bytes_written":1805252,"delete_count":0,"lbm_write_time_us":1802,"lbm_writes_lt_1ms":47,"reinsert_count":0,"update_count":220}
I20260812 06:17:39.369598 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling MajorDeltaCompactionOp(5afacfdac0284281bbf4484aa7a756fa): perf score=1.000000
I20260812 06:17:39.570926 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: MajorDeltaCompactionOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.201s	user 0.145s	sys 0.056s Metrics: {"cfile_cache_miss":624,"cfile_cache_miss_bytes":28467024,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":478,"lbm_read_time_us":13275,"lbm_reads_lt_1ms":660,"lbm_write_time_us":36168,"lbm_writes_lt_1ms":633,"peak_mem_usage":74091738,"reinsert_count":0,"thread_start_us":309,"threads_started":5,"update_count":2950}
I20260812 06:17:39.571548 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa): perf score=10.126437
I20260812 06:17:39.616050 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.044s	user 0.025s	sys 0.017s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17932,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:39.616658 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa): perf score=2.188937
I20260812 06:17:39.633268 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.016s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6196,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:39.633863 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling MajorDeltaCompactionOp(5afacfdac0284281bbf4484aa7a756fa): perf score=1.000000
I20260812 06:17:39.787745 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: MajorDeltaCompactionOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.154s	user 0.120s	sys 0.028s 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":642,"lbm_read_time_us":8501,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25368,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:39.788303 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa): perf score=10.126437
I20260812 06:17:39.823763 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.035s	user 0.023s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15389,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":1500}
I20260812 06:17:39.824214 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa): perf score=2.188937
I20260812 06:17:39.838155 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.014s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5136,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:39.838673 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling MajorDeltaCompactionOp(5afacfdac0284281bbf4484aa7a756fa): perf score=1.000000
I20260812 06:17:39.967730 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: MajorDeltaCompactionOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.129s	user 0.091s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":589,"lbm_read_time_us":9805,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23298,"lbm_writes_lt_1ms":443,"mutex_wait_us":26,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4096,"update_count":2000}
I20260812 06:17:39.968295 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa): perf score=10.126437
I20260812 06:17:40.015973 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.047s	user 0.024s	sys 0.012s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":16348,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:40.016575 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa): perf score=2.188937
I20260812 06:17:40.028448 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.012s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4403,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:40.029053 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling MajorDeltaCompactionOp(5afacfdac0284281bbf4484aa7a756fa): perf score=1.000000
I20260812 06:17:40.179834 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: MajorDeltaCompactionOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.151s	user 0.130s	sys 0.016s 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":271,"dirs.run_cpu_time_us":1857,"dirs.run_wall_time_us":17883,"lbm_read_time_us":8863,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28871,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:40.180465 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa): perf score=10.126437
I20260812 06:17:40.228881 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.048s	user 0.019s	sys 0.028s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20268,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:40.229449 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa): perf score=2.188937
I20260812 06:17:40.246670 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.017s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5738,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:40.247069 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling MajorDeltaCompactionOp(5afacfdac0284281bbf4484aa7a756fa): perf score=1.000000
I20260812 06:17:40.390945 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: MajorDeltaCompactionOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.144s	user 0.103s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":566,"lbm_read_time_us":10418,"lbm_reads_lt_1ms":468,"lbm_write_time_us":24270,"lbm_writes_lt_1ms":443,"mutex_wait_us":270,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8704,"update_count":2000}
I20260812 06:17:40.391511 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa): perf score=10.126437
I20260812 06:17:40.434743 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.043s	user 0.026s	sys 0.013s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17303,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:40.435263 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa): perf score=2.188937
I20260812 06:17:40.450387 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5244,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:40.452445 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling MajorDeltaCompactionOp(5afacfdac0284281bbf4484aa7a756fa): perf score=1.000000
I20260812 06:17:40.575134 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: MajorDeltaCompactionOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.123s	user 0.091s	sys 0.021s 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":77,"lbm_read_time_us":7779,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20721,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4096,"update_count":2000}
I20260812 06:17:40.579708 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa): perf score=10.126437
I20260812 06:17:40.625051 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.045s	user 0.030s	sys 0.004s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15196,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:40.625516 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa): perf score=2.188937
I20260812 06:17:40.641245 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.016s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5448,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:40.641803 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling FlushMRSOp(5afacfdac0284281bbf4484aa7a756fa): perf score=1.000000
I20260812 06:17:40.673053 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: FlushMRSOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.031s	user 0.023s	sys 0.004s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":72,"dirs.run_cpu_time_us":202,"dirs.run_wall_time_us":1479,"drs_written":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1615,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:40.673849 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling LogGCOp(5afacfdac0284281bbf4484aa7a756fa): free 112239330 bytes of WAL
I20260812 06:17:40.674057 13763 log_reader.cc:385] T 5afacfdac0284281bbf4484aa7a756fa: removed 11 log segments from log reader
I20260812 06:17:40.674101 13763 log.cc:1079] T 5afacfdac0284281bbf4484aa7a756fa P d1cefeb13ffa40579a89e6a1b33a0950: Deleting log segment in path: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458671825-13662-0/minicluster-data/ts-0-root/wals/5afacfdac0284281bbf4484aa7a756fa/wal-000000003 (ops 12-16)
I20260812 06:17:40.674145 13763 log.cc:1079] T 5afacfdac0284281bbf4484aa7a756fa P d1cefeb13ffa40579a89e6a1b33a0950: Deleting log segment in path: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458671825-13662-0/minicluster-data/ts-0-root/wals/5afacfdac0284281bbf4484aa7a756fa/wal-000000004 (ops 17-21)
I20260812 06:17:40.674181 13763 log.cc:1079] T 5afacfdac0284281bbf4484aa7a756fa P d1cefeb13ffa40579a89e6a1b33a0950: Deleting log segment in path: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458671825-13662-0/minicluster-data/ts-0-root/wals/5afacfdac0284281bbf4484aa7a756fa/wal-000000005 (ops 22-26)
I20260812 06:17:40.674219 13763 log.cc:1079] T 5afacfdac0284281bbf4484aa7a756fa P d1cefeb13ffa40579a89e6a1b33a0950: Deleting log segment in path: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458671825-13662-0/minicluster-data/ts-0-root/wals/5afacfdac0284281bbf4484aa7a756fa/wal-000000006 (ops 27-31)
I20260812 06:17:40.674255 13763 log.cc:1079] T 5afacfdac0284281bbf4484aa7a756fa P d1cefeb13ffa40579a89e6a1b33a0950: Deleting log segment in path: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458671825-13662-0/minicluster-data/ts-0-root/wals/5afacfdac0284281bbf4484aa7a756fa/wal-000000007 (ops 32-36)
I20260812 06:17:40.674290 13763 log.cc:1079] T 5afacfdac0284281bbf4484aa7a756fa P d1cefeb13ffa40579a89e6a1b33a0950: Deleting log segment in path: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458671825-13662-0/minicluster-data/ts-0-root/wals/5afacfdac0284281bbf4484aa7a756fa/wal-000000008 (ops 37-41)
I20260812 06:17:40.674326 13763 log.cc:1079] T 5afacfdac0284281bbf4484aa7a756fa P d1cefeb13ffa40579a89e6a1b33a0950: Deleting log segment in path: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458671825-13662-0/minicluster-data/ts-0-root/wals/5afacfdac0284281bbf4484aa7a756fa/wal-000000009 (ops 42-46)
I20260812 06:17:40.674369 13763 log.cc:1079] T 5afacfdac0284281bbf4484aa7a756fa P d1cefeb13ffa40579a89e6a1b33a0950: Deleting log segment in path: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458671825-13662-0/minicluster-data/ts-0-root/wals/5afacfdac0284281bbf4484aa7a756fa/wal-000000010 (ops 47-50)
I20260812 06:17:40.674408 13763 log.cc:1079] T 5afacfdac0284281bbf4484aa7a756fa P d1cefeb13ffa40579a89e6a1b33a0950: Deleting log segment in path: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458671825-13662-0/minicluster-data/ts-0-root/wals/5afacfdac0284281bbf4484aa7a756fa/wal-000000011 (ops 51-55)
I20260812 06:17:40.674445 13763 log.cc:1079] T 5afacfdac0284281bbf4484aa7a756fa P d1cefeb13ffa40579a89e6a1b33a0950: Deleting log segment in path: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458671825-13662-0/minicluster-data/ts-0-root/wals/5afacfdac0284281bbf4484aa7a756fa/wal-000000012 (ops 56-60)
I20260812 06:17:40.674481 13763 log.cc:1079] T 5afacfdac0284281bbf4484aa7a756fa P d1cefeb13ffa40579a89e6a1b33a0950: Deleting log segment in path: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458671825-13662-0/minicluster-data/ts-0-root/wals/5afacfdac0284281bbf4484aa7a756fa/wal-000000013 (ops 61-65)
I20260812 06:17:40.692288 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: LogGCOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.018s	user 0.000s	sys 0.018s Metrics: {}
I20260812 06:17:40.692800 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa): perf score=2.188937
I20260812 06:17:40.717895 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.025s	user 0.003s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5306,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:40.718335 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling UndoDeltaBlockGCOp(5afacfdac0284281bbf4484aa7a756fa): 462 bytes on disk
I20260812 06:17:40.718808 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: UndoDeltaBlockGCOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4}
I20260812 06:17:40.719231 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa): perf score=2.188937
I20260812 06:17:40.733805 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5062,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:40.734352 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling MajorDeltaCompactionOp(5afacfdac0284281bbf4484aa7a756fa): perf score=1.000000
I20260812 06:17:40.918911 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: MajorDeltaCompactionOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.184s	user 0.138s	sys 0.044s 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":732,"lbm_read_time_us":13420,"lbm_reads_lt_1ms":674,"lbm_write_time_us":36932,"lbm_writes_lt_1ms":643,"mutex_wait_us":39,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1152,"thread_start_us":75,"threads_started":1,"update_count":3000}
I20260812 06:17:40.919404 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa): perf score=11.118625
I20260812 06:17:40.950189 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.031s	user 0.010s	sys 0.017s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":13569,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:17:40.950768 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa): perf score=2.188937
I20260812 06:17:40.966346 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.015s	user 0.007s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4337,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:40.967924 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling MajorDeltaCompactionOp(5afacfdac0284281bbf4484aa7a756fa): perf score=1.000000
I20260812 06:17:41.098199 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: MajorDeltaCompactionOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.129s	user 0.100s	sys 0.029s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":596,"lbm_read_time_us":8987,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23200,"lbm_writes_lt_1ms":443,"mutex_wait_us":36,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":2000}
I20260812 06:17:41.098691 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa): perf score=10.126437
I20260812 06:17:41.145750 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.047s	user 0.019s	sys 0.014s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14251,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:41.146270 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa): perf score=2.188937
I20260812 06:17:41.157460 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4116,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:41.157992 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling MajorDeltaCompactionOp(5afacfdac0284281bbf4484aa7a756fa): perf score=1.000000
I20260812 06:17:41.313473 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: MajorDeltaCompactionOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.155s	user 0.114s	sys 0.035s 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":760,"lbm_read_time_us":10457,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25231,"lbm_writes_lt_1ms":443,"mutex_wait_us":306,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9472,"update_count":2000}
I20260812 06:17:41.313989 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa): perf score=10.126437
I20260812 06:17:41.363704 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.050s	user 0.018s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17333,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:41.364176 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa): perf score=2.188937
I20260812 06:17:41.374166 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3730,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:41.374606 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling MajorDeltaCompactionOp(5afacfdac0284281bbf4484aa7a756fa): perf score=1.000000
I20260812 06:17:41.506628 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: MajorDeltaCompactionOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.132s	user 0.108s	sys 0.015s 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":1743,"lbm_read_time_us":8379,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21736,"lbm_writes_lt_1ms":443,"mutex_wait_us":459,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10624,"update_count":2000}
I20260812 06:17:41.507088 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa): perf score=10.126437
I20260812 06:17:41.540417 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.033s	user 0.021s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13944,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:41.540849 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling MajorDeltaCompactionOp(5afacfdac0284281bbf4484aa7a756fa): perf score=1.000000
I20260812 06:17:41.658815 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: MajorDeltaCompactionOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.118s	user 0.068s	sys 0.041s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569746,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":254,"lbm_read_time_us":6007,"lbm_reads_lt_1ms":363,"lbm_write_time_us":17903,"lbm_writes_lt_1ms":343,"mutex_wait_us":32,"peak_mem_usage":38262756,"reinsert_count":0,"update_count":1500}
I20260812 06:17:41.659348 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa): perf score=10.126437
I20260812 06:17:41.703712 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.044s	user 0.028s	sys 0.016s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":19261,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:41.704308 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling MajorDeltaCompactionOp(5afacfdac0284281bbf4484aa7a756fa): perf score=1.000000
I20260812 06:17:41.827762 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: MajorDeltaCompactionOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.123s	user 0.082s	sys 0.036s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569747,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":345,"lbm_read_time_us":9864,"lbm_reads_lt_1ms":367,"lbm_write_time_us":19876,"lbm_writes_lt_1ms":343,"mutex_wait_us":74,"peak_mem_usage":38262756,"reinsert_count":0,"update_count":1500}
I20260812 06:17:41.829434 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa): perf score=7.149875
I20260812 06:17:41.852898 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.023s	user 0.018s	sys 0.004s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":9644,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:17:41.853426 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa): perf score=2.188937
I20260812 06:17:41.869400 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.016s	user 0.005s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5832,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:41.872072 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling MajorDeltaCompactionOp(5afacfdac0284281bbf4484aa7a756fa): perf score=1.000000
I20260812 06:17:41.988056 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: MajorDeltaCompactionOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.116s	user 0.079s	sys 0.033s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16569856,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":736,"lbm_read_time_us":8374,"lbm_reads_lt_1ms":372,"lbm_write_time_us":18655,"lbm_writes_lt_1ms":343,"mutex_wait_us":24,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":1500}
I20260812 06:17:41.988685 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa): perf score=7.149875
I20260812 06:17:42.017709 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.029s	user 0.008s	sys 0.016s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":10160,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:17:42.018236 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa): perf score=2.188937
I20260812 06:17:42.031630 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4961,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:42.033083 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling MajorDeltaCompactionOp(5afacfdac0284281bbf4484aa7a756fa): perf score=1.000000
I20260812 06:17:42.143720 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: MajorDeltaCompactionOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.110s	user 0.088s	sys 0.019s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16569856,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":83,"lbm_read_time_us":7842,"lbm_reads_lt_1ms":364,"lbm_write_time_us":17824,"lbm_writes_lt_1ms":343,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":1500}
I20260812 06:17:42.144502 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa): perf score=10.126437
I20260812 06:17:42.179071 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.034s	user 0.018s	sys 0.012s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":14623,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:42.179517 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling FlushMRSOp(5afacfdac0284281bbf4484aa7a756fa): perf score=1.000000
I20260812 06:17:42.230618 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: FlushMRSOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.051s	user 0.034s	sys 0.001s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":66,"dirs.run_cpu_time_us":231,"dirs.run_wall_time_us":1309,"drs_written":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2022,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:17:42.231463 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling LogGCOp(5afacfdac0284281bbf4484aa7a756fa): free 124257248 bytes of WAL
I20260812 06:17:42.231712 13763 log_reader.cc:385] T 5afacfdac0284281bbf4484aa7a756fa: removed 12 log segments from log reader
I20260812 06:17:42.231762 13763 log.cc:1079] T 5afacfdac0284281bbf4484aa7a756fa P d1cefeb13ffa40579a89e6a1b33a0950: Deleting log segment in path: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458671825-13662-0/minicluster-data/ts-0-root/wals/5afacfdac0284281bbf4484aa7a756fa/wal-000000014 (ops 66-70)
I20260812 06:17:42.231798 13763 log.cc:1079] T 5afacfdac0284281bbf4484aa7a756fa P d1cefeb13ffa40579a89e6a1b33a0950: Deleting log segment in path: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458671825-13662-0/minicluster-data/ts-0-root/wals/5afacfdac0284281bbf4484aa7a756fa/wal-000000015 (ops 71-75)
I20260812 06:17:42.231834 13763 log.cc:1079] T 5afacfdac0284281bbf4484aa7a756fa P d1cefeb13ffa40579a89e6a1b33a0950: Deleting log segment in path: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458671825-13662-0/minicluster-data/ts-0-root/wals/5afacfdac0284281bbf4484aa7a756fa/wal-000000016 (ops 76-80)
I20260812 06:17:42.231856 13763 log.cc:1079] T 5afacfdac0284281bbf4484aa7a756fa P d1cefeb13ffa40579a89e6a1b33a0950: Deleting log segment in path: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458671825-13662-0/minicluster-data/ts-0-root/wals/5afacfdac0284281bbf4484aa7a756fa/wal-000000017 (ops 81-85)
I20260812 06:17:42.231885 13763 log.cc:1079] T 5afacfdac0284281bbf4484aa7a756fa P d1cefeb13ffa40579a89e6a1b33a0950: Deleting log segment in path: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458671825-13662-0/minicluster-data/ts-0-root/wals/5afacfdac0284281bbf4484aa7a756fa/wal-000000018 (ops 86-90)
I20260812 06:17:42.231922 13763 log.cc:1079] T 5afacfdac0284281bbf4484aa7a756fa P d1cefeb13ffa40579a89e6a1b33a0950: Deleting log segment in path: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458671825-13662-0/minicluster-data/ts-0-root/wals/5afacfdac0284281bbf4484aa7a756fa/wal-000000019 (ops 91-95)
I20260812 06:17:42.231952 13763 log.cc:1079] T 5afacfdac0284281bbf4484aa7a756fa P d1cefeb13ffa40579a89e6a1b33a0950: Deleting log segment in path: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458671825-13662-0/minicluster-data/ts-0-root/wals/5afacfdac0284281bbf4484aa7a756fa/wal-000000020 (ops 96-100)
I20260812 06:17:42.231984 13763 log.cc:1079] T 5afacfdac0284281bbf4484aa7a756fa P d1cefeb13ffa40579a89e6a1b33a0950: Deleting log segment in path: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458671825-13662-0/minicluster-data/ts-0-root/wals/5afacfdac0284281bbf4484aa7a756fa/wal-000000021 (ops 101-105)
I20260812 06:17:42.232012 13763 log.cc:1079] T 5afacfdac0284281bbf4484aa7a756fa P d1cefeb13ffa40579a89e6a1b33a0950: Deleting log segment in path: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458671825-13662-0/minicluster-data/ts-0-root/wals/5afacfdac0284281bbf4484aa7a756fa/wal-000000022 (ops 106-110)
I20260812 06:17:42.232040 13763 log.cc:1079] T 5afacfdac0284281bbf4484aa7a756fa P d1cefeb13ffa40579a89e6a1b33a0950: Deleting log segment in path: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458671825-13662-0/minicluster-data/ts-0-root/wals/5afacfdac0284281bbf4484aa7a756fa/wal-000000023 (ops 111-115)
I20260812 06:17:42.232067 13763 log.cc:1079] T 5afacfdac0284281bbf4484aa7a756fa P d1cefeb13ffa40579a89e6a1b33a0950: Deleting log segment in path: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458671825-13662-0/minicluster-data/ts-0-root/wals/5afacfdac0284281bbf4484aa7a756fa/wal-000000024 (ops 116-120)
I20260812 06:17:42.232095 13763 log.cc:1079] T 5afacfdac0284281bbf4484aa7a756fa P d1cefeb13ffa40579a89e6a1b33a0950: Deleting log segment in path: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458671825-13662-0/minicluster-data/ts-0-root/wals/5afacfdac0284281bbf4484aa7a756fa/wal-000000025 (ops 121-124)
I20260812 06:17:42.258545 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: LogGCOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.027s	user 0.003s	sys 0.020s Metrics: {}
I20260812 06:17:42.259006 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling UndoDeltaBlockGCOp(5afacfdac0284281bbf4484aa7a756fa): 473 bytes on disk
I20260812 06:17:42.259635 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: UndoDeltaBlockGCOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":96,"lbm_reads_lt_1ms":4}
I20260812 06:17:42.260267 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa): perf score=7.149875
I20260812 06:17:42.294490 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.034s	user 0.006s	sys 0.025s Metrics: {"bytes_written":8615324,"delete_count":0,"lbm_write_time_us":11792,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:17:42.294945 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling LogGCOp(5afacfdac0284281bbf4484aa7a756fa): free 8767068 bytes of WAL
I20260812 06:17:42.295125 13763 log_reader.cc:385] T 5afacfdac0284281bbf4484aa7a756fa: removed 1 log segments from log reader
I20260812 06:17:42.295161 13763 log.cc:1079] T 5afacfdac0284281bbf4484aa7a756fa P d1cefeb13ffa40579a89e6a1b33a0950: Deleting log segment in path: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458671825-13662-0/minicluster-data/ts-0-root/wals/5afacfdac0284281bbf4484aa7a756fa/wal-000000026 (ops 125-129)
I20260812 06:17:42.296554 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: LogGCOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.001s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:17:42.296816 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa): perf score=2.188937
I20260812 06:17:42.307438 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.010s	user 0.007s	sys 0.002s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3743,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:42.307896 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling MajorDeltaCompactionOp(5afacfdac0284281bbf4484aa7a756fa): perf score=1.000000
I20260812 06:17:42.507233 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: MajorDeltaCompactionOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.199s	user 0.150s	sys 0.046s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877215,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":175,"lbm_read_time_us":14129,"lbm_reads_lt_1ms":673,"lbm_write_time_us":35063,"lbm_writes_lt_1ms":643,"mutex_wait_us":35,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":13952,"thread_start_us":97,"threads_started":1,"update_count":3000}
I20260812 06:17:42.507818 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa): perf score=11.118625
I20260812 06:17:42.551290 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.043s	user 0.011s	sys 0.028s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14967,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:42.552031 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa): perf score=2.188937
I20260812 06:17:42.567783 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.016s	user 0.004s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4857,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:42.571980 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling MajorDeltaCompactionOp(5afacfdac0284281bbf4484aa7a756fa): perf score=1.000000
I20260812 06:17:42.739914 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: MajorDeltaCompactionOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.168s	user 0.114s	sys 0.052s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1009,"lbm_read_time_us":11642,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27444,"lbm_writes_lt_1ms":443,"mutex_wait_us":284,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12800,"update_count":2000}
I20260812 06:17:42.740495 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa): perf score=10.126437
I20260812 06:17:42.785024 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.044s	user 0.029s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16917,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:42.785540 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa): perf score=2.188937
I20260812 06:17:42.798049 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4721,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:42.799226 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling MajorDeltaCompactionOp(5afacfdac0284281bbf4484aa7a756fa): perf score=1.000000
I20260812 06:17:42.934252 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: MajorDeltaCompactionOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.135s	user 0.119s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1488,"lbm_read_time_us":9797,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24013,"lbm_writes_lt_1ms":443,"mutex_wait_us":593,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:17:42.934741 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa): perf score=10.126437
I20260812 06:17:42.976477 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.042s	user 0.030s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14532,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:42.976886 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa): perf score=2.188937
I20260812 06:17:42.994367 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.017s	user 0.009s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6305,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:42.995030 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling MajorDeltaCompactionOp(5afacfdac0284281bbf4484aa7a756fa): perf score=1.000000
I20260812 06:17:43.150816 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: MajorDeltaCompactionOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.155s	user 0.118s	sys 0.033s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":536,"lbm_read_time_us":10528,"lbm_reads_lt_1ms":472,"lbm_write_time_us":31380,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":299,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8704,"update_count":2000}
I20260812 06:17:43.151515 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa): perf score=11.118625
I20260812 06:17:43.217289 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.065s	user 0.023s	sys 0.012s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":41741,"lbm_writes_10-100_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:17:43.217798 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa): perf score=6.157687
I20260812 06:17:43.243904 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.026s	user 0.012s	sys 0.011s Metrics: {"bytes_written":7794836,"delete_count":0,"lbm_write_time_us":10482,"lbm_writes_lt_1ms":193,"reinsert_count":0,"update_count":950}
I20260812 06:17:43.244382 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling MajorDeltaCompactionOp(5afacfdac0284281bbf4484aa7a756fa): perf score=1.000000
I20260812 06:17:43.424469 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: MajorDeltaCompactionOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.180s	user 0.127s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774695,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":646,"lbm_read_time_us":12435,"lbm_reads_lt_1ms":568,"lbm_write_time_us":30191,"lbm_writes_lt_1ms":543,"mutex_wait_us":262,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:43.427616 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa): perf score=14.095187
I20260812 06:17:43.487581 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.060s	user 0.039s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20539,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:43.488319 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa): perf score=2.188937
I20260812 06:17:43.503098 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5514,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:43.503736 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling MajorDeltaCompactionOp(5afacfdac0284281bbf4484aa7a756fa): perf score=1.000000
I20260812 06:17:43.683158 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: MajorDeltaCompactionOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.179s	user 0.112s	sys 0.060s 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":801,"lbm_read_time_us":15545,"lbm_reads_1-10_ms":1,"lbm_reads_lt_1ms":571,"lbm_write_time_us":30739,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4224,"update_count":2500}
I20260812 06:17:43.683879 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa): perf score=10.126437
I20260812 06:17:43.725706 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.042s	user 0.015s	sys 0.021s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16012,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:43.732012 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa): perf score=2.188937
I20260812 06:17:43.743572 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3857,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:43.744347 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling FlushMRSOp(5afacfdac0284281bbf4484aa7a756fa): perf score=1.000000
I20260812 06:17:43.780006 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: FlushMRSOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.035s	user 0.026s	sys 0.005s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":55,"dirs.run_cpu_time_us":234,"dirs.run_wall_time_us":1678,"drs_written":1,"lbm_read_time_us":42,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2725,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:43.780882 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling LogGCOp(5afacfdac0284281bbf4484aa7a756fa): free 112692667 bytes of WAL
I20260812 06:17:43.781167 13763 log_reader.cc:385] T 5afacfdac0284281bbf4484aa7a756fa: removed 11 log segments from log reader
I20260812 06:17:43.781217 13763 log.cc:1079] T 5afacfdac0284281bbf4484aa7a756fa P d1cefeb13ffa40579a89e6a1b33a0950: Deleting log segment in path: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458671825-13662-0/minicluster-data/ts-0-root/wals/5afacfdac0284281bbf4484aa7a756fa/wal-000000027 (ops 130-134)
I20260812 06:17:43.781296 13763 log.cc:1079] T 5afacfdac0284281bbf4484aa7a756fa P d1cefeb13ffa40579a89e6a1b33a0950: Deleting log segment in path: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458671825-13662-0/minicluster-data/ts-0-root/wals/5afacfdac0284281bbf4484aa7a756fa/wal-000000028 (ops 135-139)
I20260812 06:17:43.781347 13763 log.cc:1079] T 5afacfdac0284281bbf4484aa7a756fa P d1cefeb13ffa40579a89e6a1b33a0950: Deleting log segment in path: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458671825-13662-0/minicluster-data/ts-0-root/wals/5afacfdac0284281bbf4484aa7a756fa/wal-000000029 (ops 140-144)
I20260812 06:17:43.781373 13763 log.cc:1079] T 5afacfdac0284281bbf4484aa7a756fa P d1cefeb13ffa40579a89e6a1b33a0950: Deleting log segment in path: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458671825-13662-0/minicluster-data/ts-0-root/wals/5afacfdac0284281bbf4484aa7a756fa/wal-000000030 (ops 145-149)
I20260812 06:17:43.781435 13763 log.cc:1079] T 5afacfdac0284281bbf4484aa7a756fa P d1cefeb13ffa40579a89e6a1b33a0950: Deleting log segment in path: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458671825-13662-0/minicluster-data/ts-0-root/wals/5afacfdac0284281bbf4484aa7a756fa/wal-000000031 (ops 150-154)
I20260812 06:17:43.781471 13763 log.cc:1079] T 5afacfdac0284281bbf4484aa7a756fa P d1cefeb13ffa40579a89e6a1b33a0950: Deleting log segment in path: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458671825-13662-0/minicluster-data/ts-0-root/wals/5afacfdac0284281bbf4484aa7a756fa/wal-000000032 (ops 155-159)
I20260812 06:17:43.781495 13763 log.cc:1079] T 5afacfdac0284281bbf4484aa7a756fa P d1cefeb13ffa40579a89e6a1b33a0950: Deleting log segment in path: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458671825-13662-0/minicluster-data/ts-0-root/wals/5afacfdac0284281bbf4484aa7a756fa/wal-000000033 (ops 160-164)
I20260812 06:17:43.781553 13763 log.cc:1079] T 5afacfdac0284281bbf4484aa7a756fa P d1cefeb13ffa40579a89e6a1b33a0950: Deleting log segment in path: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458671825-13662-0/minicluster-data/ts-0-root/wals/5afacfdac0284281bbf4484aa7a756fa/wal-000000034 (ops 165-169)
I20260812 06:17:43.781587 13763 log.cc:1079] T 5afacfdac0284281bbf4484aa7a756fa P d1cefeb13ffa40579a89e6a1b33a0950: Deleting log segment in path: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458671825-13662-0/minicluster-data/ts-0-root/wals/5afacfdac0284281bbf4484aa7a756fa/wal-000000035 (ops 170-174)
I20260812 06:17:43.781635 13763 log.cc:1079] T 5afacfdac0284281bbf4484aa7a756fa P d1cefeb13ffa40579a89e6a1b33a0950: Deleting log segment in path: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458671825-13662-0/minicluster-data/ts-0-root/wals/5afacfdac0284281bbf4484aa7a756fa/wal-000000036 (ops 175-179)
I20260812 06:17:43.781669 13763 log.cc:1079] T 5afacfdac0284281bbf4484aa7a756fa P d1cefeb13ffa40579a89e6a1b33a0950: Deleting log segment in path: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458671825-13662-0/minicluster-data/ts-0-root/wals/5afacfdac0284281bbf4484aa7a756fa/wal-000000037 (ops 180-184)
I20260812 06:17:43.798573 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: LogGCOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.017s	user 0.000s	sys 0.014s Metrics: {}
I20260812 06:17:43.799093 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa): perf score=2.188937
I20260812 06:17:43.815176 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.016s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5863,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:43.815868 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling MajorDeltaCompactionOp(5afacfdac0284281bbf4484aa7a756fa): perf score=1.000000
I20260812 06:17:43.994140 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: MajorDeltaCompactionOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.178s	user 0.123s	sys 0.048s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774808,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":3171,"lbm_read_time_us":10476,"lbm_reads_lt_1ms":569,"lbm_write_time_us":30487,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5760,"thread_start_us":76,"threads_started":1,"update_count":2500}
I20260812 06:17:43.995030 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling UndoDeltaBlockGCOp(5afacfdac0284281bbf4484aa7a756fa): 447 bytes on disk
I20260812 06:17:43.995528 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: UndoDeltaBlockGCOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4}
I20260812 06:17:43.996178 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa): perf score=14.095187
I20260812 06:17:44.047569 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.051s	user 0.024s	sys 0.019s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19772,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:44.048121 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa): perf score=2.188937
I20260812 06:17:44.063372 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.015s	user 0.012s	sys 0.001s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5757,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:44.064148 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling MajorDeltaCompactionOp(5afacfdac0284281bbf4484aa7a756fa): perf score=1.000000
I20260812 06:17:44.230295 13662 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.265s	user 1.842s	sys 0.146s
I20260812 06:17:44.232309 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: MajorDeltaCompactionOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.168s	user 0.114s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1215,"lbm_read_time_us":10955,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25276,"lbm_writes_lt_1ms":543,"mutex_wait_us":426,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:44.232834 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa): perf score=10.126437
I20260812 06:17:44.263809 13662 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.033s	user 0.006s	sys 0.000s
I20260812 06:17:44.264667 13662 tablet_server.cc:179] TabletServer@127.13.87.129:0 shutting down...
I20260812 06:17:44.271441 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: FlushDeltaMemStoresOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.038s	user 0.017s	sys 0.017s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":15877,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:44.272038 13823 maintenance_manager.cc:419] P d1cefeb13ffa40579a89e6a1b33a0950: Scheduling MajorDeltaCompactionOp(5afacfdac0284281bbf4484aa7a756fa): perf score=1.000000
I20260812 06:17:44.371659 13763 maintenance_manager.cc:643] P d1cefeb13ffa40579a89e6a1b33a0950: MajorDeltaCompactionOp(5afacfdac0284281bbf4484aa7a756fa) complete. Timing: real 0.099s	user 0.071s	sys 0.027s Metrics: {"cfile_cache_hit":30,"cfile_cache_hit_bytes":4262390,"cfile_cache_miss":301,"cfile_cache_miss_bytes":12307358,"cfile_init":3,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":480,"lbm_read_time_us":4532,"lbm_reads_lt_1ms":313,"lbm_write_time_us":17737,"lbm_writes_lt_1ms":343,"mutex_wait_us":53,"peak_mem_usage":38262756,"reinsert_count":0,"update_count":1500}
I20260812 06:17:44.372393 13662 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:44.372920 13662 tablet_replica.cc:333] T 5afacfdac0284281bbf4484aa7a756fa P d1cefeb13ffa40579a89e6a1b33a0950: stopping tablet replica
I20260812 06:17:44.373149 13662 raft_consensus.cc:2243] T 5afacfdac0284281bbf4484aa7a756fa P d1cefeb13ffa40579a89e6a1b33a0950 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:44.373374 13662 raft_consensus.cc:2272] T 5afacfdac0284281bbf4484aa7a756fa P d1cefeb13ffa40579a89e6a1b33a0950 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:44.378993 13662 tablet_server.cc:196] TabletServer@127.13.87.129:0 shutdown complete.
I20260812 06:17:44.403545 13662 master.cc:562] Master@127.13.87.190:35689 shutting down...
I20260812 06:17:44.406697 13662 raft_consensus.cc:2243] T 00000000000000000000000000000000 P ae80b58b74fd4ed7b2f70c217ce71b4b [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:44.406879 13662 raft_consensus.cc:2272] T 00000000000000000000000000000000 P ae80b58b74fd4ed7b2f70c217ce71b4b [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:44.406948 13662 tablet_replica.cc:333] T 00000000000000000000000000000000 P ae80b58b74fd4ed7b2f70c217ce71b4b: stopping tablet replica
I20260812 06:17:44.419376 13662 master.cc:584] Master@127.13.87.190:35689 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5809 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:17:44.491304 13662 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.13.87.190:42339
I20260812 06:17:44.491770 13662 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:44.493637 13858 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:17:44.493811 13662 server_base.cc:1061] running on GCE node
W20260812 06:17:44.493675 13859 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:44.493901 13861 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:17:44.494125 13662 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:44.494180 13662 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:17:44.494199 13662 hybrid_clock.cc:648] HybridClock initialized: now 1786515464494199 us; error 0 us; skew 500 ppm
I20260812 06:17:44.495023 13662 webserver.cc:533] Webserver started at http://127.13.87.190:40189/ using document root <none> and password file <none>
I20260812 06:17:44.495170 13662 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:44.495219 13662 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:44.495286 13662 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:44.495715 13662 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458671825-13662-0/minicluster-data/master-0-root/instance:
uuid: "ae1b991d0c1242ab97afc1f181832ae6"
format_stamp: "Formatted at 2026-08-12 06:17:44 on dist-test-slave-f7th"
I20260812 06:17:44.497399 13662 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:44.498399 13866 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:17:44.498693 13662 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:44.498768 13662 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458671825-13662-0/minicluster-data/master-0-root
uuid: "ae1b991d0c1242ab97afc1f181832ae6"
format_stamp: "Formatted at 2026-08-12 06:17:44 on dist-test-slave-f7th"
I20260812 06:17:44.498832 13662 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458671825-13662-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458671825-13662-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458671825-13662-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:17:44.510702 13662 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:44.511076 13662 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:44.515674 13662 rpc_server.cc:307] RPC server started. Bound to: 127.13.87.190:42339
I20260812 06:17:44.522123 13918 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.13.87.190:42339 every 8 connection(s)
I20260812 06:17:44.522562 13919 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:17:44.524340 13919 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P ae1b991d0c1242ab97afc1f181832ae6: Bootstrap starting.
I20260812 06:17:44.525061 13919 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P ae1b991d0c1242ab97afc1f181832ae6: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:44.526098 13919 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P ae1b991d0c1242ab97afc1f181832ae6: No bootstrap required, opened a new log
I20260812 06:17:44.526517 13919 raft_consensus.cc:359] T 00000000000000000000000000000000 P ae1b991d0c1242ab97afc1f181832ae6 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ae1b991d0c1242ab97afc1f181832ae6" member_type: VOTER }
I20260812 06:17:44.526604 13919 raft_consensus.cc:385] T 00000000000000000000000000000000 P ae1b991d0c1242ab97afc1f181832ae6 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:44.526626 13919 raft_consensus.cc:740] T 00000000000000000000000000000000 P ae1b991d0c1242ab97afc1f181832ae6 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: ae1b991d0c1242ab97afc1f181832ae6, State: Initialized, Role: FOLLOWER
I20260812 06:17:44.526763 13919 consensus_queue.cc:260] T 00000000000000000000000000000000 P ae1b991d0c1242ab97afc1f181832ae6 [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: "ae1b991d0c1242ab97afc1f181832ae6" member_type: VOTER }
I20260812 06:17:44.526860 13919 raft_consensus.cc:399] T 00000000000000000000000000000000 P ae1b991d0c1242ab97afc1f181832ae6 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:44.526891 13919 raft_consensus.cc:493] T 00000000000000000000000000000000 P ae1b991d0c1242ab97afc1f181832ae6 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:44.526932 13919 raft_consensus.cc:3060] T 00000000000000000000000000000000 P ae1b991d0c1242ab97afc1f181832ae6 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:44.527676 13919 raft_consensus.cc:515] T 00000000000000000000000000000000 P ae1b991d0c1242ab97afc1f181832ae6 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ae1b991d0c1242ab97afc1f181832ae6" member_type: VOTER }
I20260812 06:17:44.527801 13919 leader_election.cc:304] T 00000000000000000000000000000000 P ae1b991d0c1242ab97afc1f181832ae6 [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: ae1b991d0c1242ab97afc1f181832ae6; no voters: 
I20260812 06:17:44.527976 13919 leader_election.cc:290] T 00000000000000000000000000000000 P ae1b991d0c1242ab97afc1f181832ae6 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:44.528074 13922 raft_consensus.cc:2804] T 00000000000000000000000000000000 P ae1b991d0c1242ab97afc1f181832ae6 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:44.528312 13922 raft_consensus.cc:697] T 00000000000000000000000000000000 P ae1b991d0c1242ab97afc1f181832ae6 [term 1 LEADER]: Becoming Leader. State: Replica: ae1b991d0c1242ab97afc1f181832ae6, State: Running, Role: LEADER
I20260812 06:17:44.528429 13919 sys_catalog.cc:565] T 00000000000000000000000000000000 P ae1b991d0c1242ab97afc1f181832ae6 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:44.528482 13922 consensus_queue.cc:237] T 00000000000000000000000000000000 P ae1b991d0c1242ab97afc1f181832ae6 [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: "ae1b991d0c1242ab97afc1f181832ae6" member_type: VOTER }
I20260812 06:17:44.528865 13923 sys_catalog.cc:455] T 00000000000000000000000000000000 P ae1b991d0c1242ab97afc1f181832ae6 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "ae1b991d0c1242ab97afc1f181832ae6" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ae1b991d0c1242ab97afc1f181832ae6" member_type: VOTER } }
I20260812 06:17:44.528952 13923 sys_catalog.cc:458] T 00000000000000000000000000000000 P ae1b991d0c1242ab97afc1f181832ae6 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:44.529217 13926 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:44.529215 13924 sys_catalog.cc:455] T 00000000000000000000000000000000 P ae1b991d0c1242ab97afc1f181832ae6 [sys.catalog]: SysCatalogTable state changed. Reason: New leader ae1b991d0c1242ab97afc1f181832ae6. Latest consensus state: current_term: 1 leader_uuid: "ae1b991d0c1242ab97afc1f181832ae6" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ae1b991d0c1242ab97afc1f181832ae6" member_type: VOTER } }
I20260812 06:17:44.529666 13924 sys_catalog.cc:458] T 00000000000000000000000000000000 P ae1b991d0c1242ab97afc1f181832ae6 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:44.530061 13926 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:44.530277 13662 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:44.531787 13926 catalog_manager.cc:1383] Generated new cluster ID: 2e4e71788c59423289e9d5dd6a4c0203
I20260812 06:17:44.531841 13926 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:44.548297 13926 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:44.548825 13926 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:44.554020 13926 catalog_manager.cc:6092] T 00000000000000000000000000000000 P ae1b991d0c1242ab97afc1f181832ae6: Generated new TSK 0
I20260812 06:17:44.554165 13926 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:44.562422 13662 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:44.564325 13940 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:17:44.564360 13941 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:17:44.564489 13662 server_base.cc:1061] running on GCE node
W20260812 06:17:44.564376 13943 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:17:44.564739 13662 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:44.564781 13662 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:17:44.564795 13662 hybrid_clock.cc:648] HybridClock initialized: now 1786515464564795 us; error 0 us; skew 500 ppm
I20260812 06:17:44.565584 13662 webserver.cc:533] Webserver started at http://127.13.87.129:44541/ using document root <none> and password file <none>
I20260812 06:17:44.565725 13662 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:44.565774 13662 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:44.565845 13662 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:44.566211 13662 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458671825-13662-0/minicluster-data/ts-0-root/instance:
uuid: "fa371085a23d4df2b789a40c6cef29d2"
format_stamp: "Formatted at 2026-08-12 06:17:44 on dist-test-slave-f7th"
I20260812 06:17:44.567582 13662 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.001s
I20260812 06:17:44.568511 13948 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:17:44.568727 13662 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:17:44.568791 13662 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458671825-13662-0/minicluster-data/ts-0-root
uuid: "fa371085a23d4df2b789a40c6cef29d2"
format_stamp: "Formatted at 2026-08-12 06:17:44 on dist-test-slave-f7th"
I20260812 06:17:44.568856 13662 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458671825-13662-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458671825-13662-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458671825-13662-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:17:44.586067 13662 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:44.586416 13662 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:44.586684 13662 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:44.587117 13662 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:44.587154 13662 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:44.587206 13662 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:44.587234 13662 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:44.591265 13662 rpc_server.cc:307] RPC server started. Bound to: 127.13.87.129:42167
I20260812 06:17:44.592248 14011 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.13.87.129:42167 every 8 connection(s)
I20260812 06:17:44.599833 14012 heartbeater.cc:344] Connected to a master server at 127.13.87.190:42339
I20260812 06:17:44.599943 14012 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:44.600165 14012 heartbeater.cc:507] Master 127.13.87.190:42339 requested a full tablet report, sending...
I20260812 06:17:44.600824 13883 ts_manager.cc:194] Registered new tserver with Master: fa371085a23d4df2b789a40c6cef29d2 (127.13.87.129:42167)
I20260812 06:17:44.601140 13662 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.00912829s
I20260812 06:17:44.601773 13883 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:43490
I20260812 06:17:44.608575 13883 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:43500:
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:17:44.616997 13976 tablet_service.cc:1511] Processing CreateTablet for tablet 45ddd260996746ecbd367a7bbf444fe1 (DEFAULT_TABLE table=heavy-update-compaction-test [id=8ac98a995aeb4d0485b1dd8e5a7397c4]), partition=
I20260812 06:17:44.617250 13976 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 45ddd260996746ecbd367a7bbf444fe1. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:44.619042 14024 tablet_bootstrap.cc:492] T 45ddd260996746ecbd367a7bbf444fe1 P fa371085a23d4df2b789a40c6cef29d2: Bootstrap starting.
I20260812 06:17:44.620051 14024 tablet_bootstrap.cc:654] T 45ddd260996746ecbd367a7bbf444fe1 P fa371085a23d4df2b789a40c6cef29d2: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:44.621176 14024 tablet_bootstrap.cc:492] T 45ddd260996746ecbd367a7bbf444fe1 P fa371085a23d4df2b789a40c6cef29d2: No bootstrap required, opened a new log
I20260812 06:17:44.621263 14024 ts_tablet_manager.cc:1403] T 45ddd260996746ecbd367a7bbf444fe1 P fa371085a23d4df2b789a40c6cef29d2: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:44.621733 14024 raft_consensus.cc:359] T 45ddd260996746ecbd367a7bbf444fe1 P fa371085a23d4df2b789a40c6cef29d2 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "fa371085a23d4df2b789a40c6cef29d2" member_type: VOTER last_known_addr { host: "127.13.87.129" port: 42167 } }
I20260812 06:17:44.621833 14024 raft_consensus.cc:385] T 45ddd260996746ecbd367a7bbf444fe1 P fa371085a23d4df2b789a40c6cef29d2 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:44.621901 14024 raft_consensus.cc:740] T 45ddd260996746ecbd367a7bbf444fe1 P fa371085a23d4df2b789a40c6cef29d2 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: fa371085a23d4df2b789a40c6cef29d2, State: Initialized, Role: FOLLOWER
I20260812 06:17:44.622041 14024 consensus_queue.cc:260] T 45ddd260996746ecbd367a7bbf444fe1 P fa371085a23d4df2b789a40c6cef29d2 [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: "fa371085a23d4df2b789a40c6cef29d2" member_type: VOTER last_known_addr { host: "127.13.87.129" port: 42167 } }
I20260812 06:17:44.622123 14024 raft_consensus.cc:399] T 45ddd260996746ecbd367a7bbf444fe1 P fa371085a23d4df2b789a40c6cef29d2 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:44.622159 14024 raft_consensus.cc:493] T 45ddd260996746ecbd367a7bbf444fe1 P fa371085a23d4df2b789a40c6cef29d2 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:44.622195 14024 raft_consensus.cc:3060] T 45ddd260996746ecbd367a7bbf444fe1 P fa371085a23d4df2b789a40c6cef29d2 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:44.623055 14024 raft_consensus.cc:515] T 45ddd260996746ecbd367a7bbf444fe1 P fa371085a23d4df2b789a40c6cef29d2 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "fa371085a23d4df2b789a40c6cef29d2" member_type: VOTER last_known_addr { host: "127.13.87.129" port: 42167 } }
I20260812 06:17:44.623196 14024 leader_election.cc:304] T 45ddd260996746ecbd367a7bbf444fe1 P fa371085a23d4df2b789a40c6cef29d2 [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: fa371085a23d4df2b789a40c6cef29d2; no voters: 
I20260812 06:17:44.623371 14024 leader_election.cc:290] T 45ddd260996746ecbd367a7bbf444fe1 P fa371085a23d4df2b789a40c6cef29d2 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:44.623469 14026 raft_consensus.cc:2804] T 45ddd260996746ecbd367a7bbf444fe1 P fa371085a23d4df2b789a40c6cef29d2 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:44.623678 14024 ts_tablet_manager.cc:1434] T 45ddd260996746ecbd367a7bbf444fe1 P fa371085a23d4df2b789a40c6cef29d2: Time spent starting tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:44.623713 14012 heartbeater.cc:499] Master 127.13.87.190:42339 was elected leader, sending a full tablet report...
I20260812 06:17:44.623733 14026 raft_consensus.cc:697] T 45ddd260996746ecbd367a7bbf444fe1 P fa371085a23d4df2b789a40c6cef29d2 [term 1 LEADER]: Becoming Leader. State: Replica: fa371085a23d4df2b789a40c6cef29d2, State: Running, Role: LEADER
I20260812 06:17:44.624023 14026 consensus_queue.cc:237] T 45ddd260996746ecbd367a7bbf444fe1 P fa371085a23d4df2b789a40c6cef29d2 [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: "fa371085a23d4df2b789a40c6cef29d2" member_type: VOTER last_known_addr { host: "127.13.87.129" port: 42167 } }
I20260812 06:17:44.625105 13883 catalog_manager.cc:5719] T 45ddd260996746ecbd367a7bbf444fe1 P fa371085a23d4df2b789a40c6cef29d2 reported cstate change: term changed from 0 to 1, leader changed from <none> to fa371085a23d4df2b789a40c6cef29d2 (127.13.87.129). New cstate: current_term: 1 leader_uuid: "fa371085a23d4df2b789a40c6cef29d2" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "fa371085a23d4df2b789a40c6cef29d2" member_type: VOTER last_known_addr { host: "127.13.87.129" port: 42167 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:44.682664 13662 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.050s	user 0.019s	sys 0.002s
I20260812 06:17:44.842777 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling FlushMRSOp(45ddd260996746ecbd367a7bbf444fe1): perf score=19.054940
I20260812 06:17:45.017683 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: FlushMRSOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.175s	user 0.124s	sys 0.046s Metrics: {"bytes_written":15999661,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":51,"dirs.run_cpu_time_us":184,"dirs.run_wall_time_us":758,"drs_written":1,"lbm_read_time_us":45,"lbm_reads_lt_1ms":4,"lbm_write_time_us":44202,"lbm_writes_lt_1ms":857,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"update_count":1950}
I20260812 06:17:45.018488 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling LogGCOp(45ddd260996746ecbd367a7bbf444fe1): free 20743880 bytes of WAL
I20260812 06:17:45.018829 13953 log_reader.cc:385] T 45ddd260996746ecbd367a7bbf444fe1: removed 2 log segments from log reader
I20260812 06:17:45.018947 13953 log.cc:1079] T 45ddd260996746ecbd367a7bbf444fe1 P fa371085a23d4df2b789a40c6cef29d2: Deleting log segment in path: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458671825-13662-0/minicluster-data/ts-0-root/wals/45ddd260996746ecbd367a7bbf444fe1/wal-000000001 (ops 1-6)
I20260812 06:17:45.019039 13953 log.cc:1079] T 45ddd260996746ecbd367a7bbf444fe1 P fa371085a23d4df2b789a40c6cef29d2: Deleting log segment in path: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458671825-13662-0/minicluster-data/ts-0-root/wals/45ddd260996746ecbd367a7bbf444fe1/wal-000000002 (ops 7-11)
I20260812 06:17:45.022541 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: LogGCOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.004s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:17:45.022882 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling UndoDeltaBlockGCOp(45ddd260996746ecbd367a7bbf444fe1): 16821651 bytes on disk
I20260812 06:17:45.023320 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: UndoDeltaBlockGCOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4}
I20260812 06:17:45.023763 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1): perf score=3.181125
I20260812 06:17:45.049333 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.025s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":5433,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:45.049860 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1): perf score=2.188937
I20260812 06:17:45.064806 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5377,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:45.065425 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling MajorDeltaCompactionOp(45ddd260996746ecbd367a7bbf444fe1): perf score=1.000000
I20260812 06:17:45.260720 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: MajorDeltaCompactionOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.195s	user 0.149s	sys 0.036s Metrics: {"cfile_cache_miss":623,"cfile_cache_miss_bytes":28507964,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":446,"lbm_read_time_us":14692,"lbm_reads_lt_1ms":659,"lbm_write_time_us":30632,"lbm_writes_lt_1ms":633,"mutex_wait_us":38,"peak_mem_usage":74091738,"reinsert_count":0,"spinlock_wait_cycles":3328,"thread_start_us":284,"threads_started":5,"update_count":2950}
I20260812 06:17:45.261302 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1): perf score=14.095187
I20260812 06:17:45.315966 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.054s	user 0.036s	sys 0.012s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":20893,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:45.316726 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1): perf score=2.188937
I20260812 06:17:45.327569 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4096,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:45.327996 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling MajorDeltaCompactionOp(45ddd260996746ecbd367a7bbf444fe1): perf score=1.000000
I20260812 06:17:45.476362 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: MajorDeltaCompactionOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.148s	user 0.117s	sys 0.029s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1217,"lbm_read_time_us":9758,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27116,"lbm_writes_lt_1ms":543,"mutex_wait_us":296,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3584,"update_count":2500}
I20260812 06:17:45.476912 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1): perf score=10.126437
I20260812 06:17:45.506121 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.029s	user 0.005s	sys 0.021s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12347,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:45.506672 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling MajorDeltaCompactionOp(45ddd260996746ecbd367a7bbf444fe1): perf score=1.000000
I20260812 06:17:45.622701 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: MajorDeltaCompactionOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.116s	user 0.076s	sys 0.040s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16610741,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":771,"lbm_read_time_us":10161,"lbm_reads_lt_1ms":367,"lbm_write_time_us":16332,"lbm_writes_lt_1ms":343,"mutex_wait_us":250,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":15616,"update_count":1500}
I20260812 06:17:45.623198 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1): perf score=6.157687
I20260812 06:17:45.662757 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.039s	user 0.018s	sys 0.007s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":11603,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:17:45.663302 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1): perf score=2.188937
I20260812 06:17:45.679392 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.016s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6419,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:45.680040 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling MajorDeltaCompactionOp(45ddd260996746ecbd367a7bbf444fe1): perf score=1.000000
I20260812 06:17:45.812796 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: MajorDeltaCompactionOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.133s	user 0.119s	sys 0.012s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16610860,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":530,"lbm_read_time_us":8363,"lbm_reads_lt_1ms":364,"lbm_write_time_us":23807,"lbm_writes_lt_1ms":343,"mutex_wait_us":250,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":3072,"update_count":1500}
I20260812 06:17:45.813347 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1): perf score=10.126437
I20260812 06:17:45.858207 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.045s	user 0.023s	sys 0.008s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":14617,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:45.858845 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1): perf score=2.188937
I20260812 06:17:45.873112 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5439,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:45.873595 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling MajorDeltaCompactionOp(45ddd260996746ecbd367a7bbf444fe1): perf score=1.000000
I20260812 06:17:46.023157 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: MajorDeltaCompactionOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.149s	user 0.090s	sys 0.044s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713274,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":824,"lbm_read_time_us":9249,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26050,"lbm_writes_lt_1ms":443,"mutex_wait_us":274,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4864,"update_count":2000}
I20260812 06:17:46.023808 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1): perf score=10.126437
I20260812 06:17:46.067004 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.043s	user 0.032s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19992,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:46.067548 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1): perf score=2.188937
I20260812 06:17:46.092454 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.025s	user 0.015s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6660,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:46.092873 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling MajorDeltaCompactionOp(45ddd260996746ecbd367a7bbf444fe1): perf score=1.000000
I20260812 06:17:46.249042 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: MajorDeltaCompactionOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.156s	user 0.107s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":444,"lbm_read_time_us":11878,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23311,"lbm_writes_lt_1ms":443,"mutex_wait_us":239,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5120,"update_count":2000}
I20260812 06:17:46.249598 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1): perf score=10.126437
I20260812 06:17:46.286053 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.036s	user 0.021s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15044,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:46.286643 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1): perf score=2.188937
I20260812 06:17:46.299355 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.013s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5025,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:46.299875 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling FlushMRSOp(45ddd260996746ecbd367a7bbf444fe1): perf score=1.000000
I20260812 06:17:46.331339 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: FlushMRSOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.031s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":71,"dirs.run_cpu_time_us":192,"dirs.run_wall_time_us":1413,"drs_written":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1580,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:46.332015 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling LogGCOp(45ddd260996746ecbd367a7bbf444fe1): free 120553319 bytes of WAL
I20260812 06:17:46.332221 13953 log_reader.cc:385] T 45ddd260996746ecbd367a7bbf444fe1: removed 12 log segments from log reader
I20260812 06:17:46.332268 13953 log.cc:1079] T 45ddd260996746ecbd367a7bbf444fe1 P fa371085a23d4df2b789a40c6cef29d2: Deleting log segment in path: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458671825-13662-0/minicluster-data/ts-0-root/wals/45ddd260996746ecbd367a7bbf444fe1/wal-000000003 (ops 12-16)
I20260812 06:17:46.332300 13953 log.cc:1079] T 45ddd260996746ecbd367a7bbf444fe1 P fa371085a23d4df2b789a40c6cef29d2: Deleting log segment in path: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458671825-13662-0/minicluster-data/ts-0-root/wals/45ddd260996746ecbd367a7bbf444fe1/wal-000000004 (ops 17-20)
I20260812 06:17:46.332327 13953 log.cc:1079] T 45ddd260996746ecbd367a7bbf444fe1 P fa371085a23d4df2b789a40c6cef29d2: Deleting log segment in path: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458671825-13662-0/minicluster-data/ts-0-root/wals/45ddd260996746ecbd367a7bbf444fe1/wal-000000005 (ops 21-25)
I20260812 06:17:46.332391 13953 log.cc:1079] T 45ddd260996746ecbd367a7bbf444fe1 P fa371085a23d4df2b789a40c6cef29d2: Deleting log segment in path: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458671825-13662-0/minicluster-data/ts-0-root/wals/45ddd260996746ecbd367a7bbf444fe1/wal-000000006 (ops 26-30)
I20260812 06:17:46.332422 13953 log.cc:1079] T 45ddd260996746ecbd367a7bbf444fe1 P fa371085a23d4df2b789a40c6cef29d2: Deleting log segment in path: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458671825-13662-0/minicluster-data/ts-0-root/wals/45ddd260996746ecbd367a7bbf444fe1/wal-000000007 (ops 31-35)
I20260812 06:17:46.332460 13953 log.cc:1079] T 45ddd260996746ecbd367a7bbf444fe1 P fa371085a23d4df2b789a40c6cef29d2: Deleting log segment in path: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458671825-13662-0/minicluster-data/ts-0-root/wals/45ddd260996746ecbd367a7bbf444fe1/wal-000000008 (ops 36-40)
I20260812 06:17:46.332489 13953 log.cc:1079] T 45ddd260996746ecbd367a7bbf444fe1 P fa371085a23d4df2b789a40c6cef29d2: Deleting log segment in path: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458671825-13662-0/minicluster-data/ts-0-root/wals/45ddd260996746ecbd367a7bbf444fe1/wal-000000009 (ops 41-44)
I20260812 06:17:46.332545 13953 log.cc:1079] T 45ddd260996746ecbd367a7bbf444fe1 P fa371085a23d4df2b789a40c6cef29d2: Deleting log segment in path: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458671825-13662-0/minicluster-data/ts-0-root/wals/45ddd260996746ecbd367a7bbf444fe1/wal-000000010 (ops 45-49)
I20260812 06:17:46.332577 13953 log.cc:1079] T 45ddd260996746ecbd367a7bbf444fe1 P fa371085a23d4df2b789a40c6cef29d2: Deleting log segment in path: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458671825-13662-0/minicluster-data/ts-0-root/wals/45ddd260996746ecbd367a7bbf444fe1/wal-000000011 (ops 50-54)
I20260812 06:17:46.332597 13953 log.cc:1079] T 45ddd260996746ecbd367a7bbf444fe1 P fa371085a23d4df2b789a40c6cef29d2: Deleting log segment in path: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458671825-13662-0/minicluster-data/ts-0-root/wals/45ddd260996746ecbd367a7bbf444fe1/wal-000000012 (ops 55-59)
I20260812 06:17:46.332643 13953 log.cc:1079] T 45ddd260996746ecbd367a7bbf444fe1 P fa371085a23d4df2b789a40c6cef29d2: Deleting log segment in path: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458671825-13662-0/minicluster-data/ts-0-root/wals/45ddd260996746ecbd367a7bbf444fe1/wal-000000013 (ops 60-64)
I20260812 06:17:46.332674 13953 log.cc:1079] T 45ddd260996746ecbd367a7bbf444fe1 P fa371085a23d4df2b789a40c6cef29d2: Deleting log segment in path: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458671825-13662-0/minicluster-data/ts-0-root/wals/45ddd260996746ecbd367a7bbf444fe1/wal-000000014 (ops 65-69)
I20260812 06:17:46.356545 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: LogGCOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.024s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:17:46.356899 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1): perf score=3.181125
I20260812 06:17:46.373075 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.016s	user 0.001s	sys 0.011s Metrics: {"bytes_written":4512904,"delete_count":0,"lbm_write_time_us":5266,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:46.373580 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling UndoDeltaBlockGCOp(45ddd260996746ecbd367a7bbf444fe1): 447 bytes on disk
I20260812 06:17:46.374010 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: UndoDeltaBlockGCOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4}
I20260812 06:17:46.374436 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1): perf score=2.188937
I20260812 06:17:46.384383 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.010s	user 0.000s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3738,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:46.384768 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling MajorDeltaCompactionOp(45ddd260996746ecbd367a7bbf444fe1): perf score=1.000000
I20260812 06:17:46.594913 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: MajorDeltaCompactionOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.210s	user 0.126s	sys 0.078s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918325,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":223,"lbm_read_time_us":13955,"lbm_reads_lt_1ms":674,"lbm_write_time_us":33657,"lbm_writes_lt_1ms":643,"mutex_wait_us":59,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3200,"thread_start_us":89,"threads_started":1,"update_count":3000}
I20260812 06:17:46.595825 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1): perf score=14.095187
I20260812 06:17:46.650146 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.054s	user 0.038s	sys 0.012s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23935,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:46.650694 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1): perf score=3.181125
I20260812 06:17:46.671186 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.020s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":5834,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:46.671674 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling MajorDeltaCompactionOp(45ddd260996746ecbd367a7bbf444fe1): perf score=1.000000
I20260812 06:17:46.860986 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: MajorDeltaCompactionOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.189s	user 0.120s	sys 0.064s Metrics: {"cfile_cache_miss":542,"cfile_cache_miss_bytes":25225928,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":715,"lbm_read_time_us":12621,"lbm_reads_lt_1ms":574,"lbm_write_time_us":30103,"lbm_writes_lt_1ms":553,"mutex_wait_us":284,"peak_mem_usage":63526250,"reinsert_count":0,"spinlock_wait_cycles":12416,"update_count":2550}
I20260812 06:17:46.864892 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1): perf score=14.095187
I20260812 06:17:46.917689 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.053s	user 0.030s	sys 0.012s Metrics: {"bytes_written":15999660,"delete_count":0,"lbm_write_time_us":19085,"lbm_writes_lt_1ms":393,"reinsert_count":0,"update_count":1950}
I20260812 06:17:46.918155 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1): perf score=2.188937
I20260812 06:17:46.933241 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.015s	user 0.004s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5564,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:46.933780 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling MajorDeltaCompactionOp(45ddd260996746ecbd367a7bbf444fe1): perf score=1.000000
I20260812 06:17:47.096905 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: MajorDeltaCompactionOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.163s	user 0.113s	sys 0.046s Metrics: {"cfile_cache_miss":522,"cfile_cache_miss_bytes":24405442,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":103,"lbm_read_time_us":11939,"lbm_reads_lt_1ms":562,"lbm_write_time_us":28006,"lbm_writes_lt_1ms":533,"mutex_wait_us":29,"peak_mem_usage":61665166,"reinsert_count":0,"spinlock_wait_cycles":20096,"update_count":2450}
I20260812 06:17:47.097559 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1): perf score=10.126437
I20260812 06:17:47.134930 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.037s	user 0.023s	sys 0.005s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13093,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:47.135474 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1): perf score=2.188937
I20260812 06:17:47.150468 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.015s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5211,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:47.151070 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling MajorDeltaCompactionOp(45ddd260996746ecbd367a7bbf444fe1): perf score=1.000000
I20260812 06:17:47.271227 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: MajorDeltaCompactionOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.120s	user 0.087s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":536,"lbm_read_time_us":8451,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21477,"lbm_writes_lt_1ms":443,"mutex_wait_us":263,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3840,"update_count":2000}
I20260812 06:17:47.271740 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1): perf score=7.149875
I20260812 06:17:47.298857 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.027s	user 0.012s	sys 0.012s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":11116,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:17:47.299363 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1): perf score=2.188937
I20260812 06:17:47.313934 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.014s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4690,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:47.314424 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling MajorDeltaCompactionOp(45ddd260996746ecbd367a7bbf444fe1): perf score=1.000000
I20260812 06:17:47.447379 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: MajorDeltaCompactionOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.133s	user 0.108s	sys 0.016s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16610851,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":84,"lbm_read_time_us":6514,"lbm_reads_lt_1ms":372,"lbm_write_time_us":23514,"lbm_writes_lt_1ms":343,"mutex_wait_us":67,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":1500}
I20260812 06:17:47.449430 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1): perf score=10.126437
I20260812 06:17:47.492818 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.043s	user 0.026s	sys 0.012s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":17009,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:47.493355 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1): perf score=2.188937
I20260812 06:17:47.508227 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.015s	user 0.002s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5553,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:47.508682 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling MajorDeltaCompactionOp(45ddd260996746ecbd367a7bbf444fe1): perf score=1.000000
I20260812 06:17:47.660871 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: MajorDeltaCompactionOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.152s	user 0.113s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713271,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":180,"lbm_read_time_us":9789,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24024,"lbm_writes_lt_1ms":443,"mutex_wait_us":33,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3072,"update_count":2000}
I20260812 06:17:47.661401 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1): perf score=10.126437
I20260812 06:17:47.704393 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.042s	user 0.020s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14011,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:47.704912 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1): perf score=2.188937
I20260812 06:17:47.717260 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4536,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:47.717813 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling MajorDeltaCompactionOp(45ddd260996746ecbd367a7bbf444fe1): perf score=1.000000
I20260812 06:17:47.843621 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: MajorDeltaCompactionOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.126s	user 0.085s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":795,"lbm_read_time_us":9888,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21166,"lbm_writes_lt_1ms":443,"mutex_wait_us":39,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12544,"update_count":2000}
I20260812 06:17:47.844432 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1): perf score=7.149875
I20260812 06:17:47.874531 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.029s	user 0.016s	sys 0.003s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":8800,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:17:47.875064 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1): perf score=2.188937
I20260812 06:17:47.885306 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.010s	user 0.006s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3859,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:47.885725 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling FlushMRSOp(45ddd260996746ecbd367a7bbf444fe1): perf score=1.000000
I20260812 06:17:47.921610 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: FlushMRSOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.036s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":68,"dirs.run_cpu_time_us":223,"dirs.run_wall_time_us":1218,"drs_written":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1654,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:17:47.922349 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling LogGCOp(45ddd260996746ecbd367a7bbf444fe1): free 120553431 bytes of WAL
I20260812 06:17:47.922611 13953 log_reader.cc:385] T 45ddd260996746ecbd367a7bbf444fe1: removed 12 log segments from log reader
I20260812 06:17:47.922699 13953 log.cc:1079] T 45ddd260996746ecbd367a7bbf444fe1 P fa371085a23d4df2b789a40c6cef29d2: Deleting log segment in path: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458671825-13662-0/minicluster-data/ts-0-root/wals/45ddd260996746ecbd367a7bbf444fe1/wal-000000015 (ops 70-74)
I20260812 06:17:47.922775 13953 log.cc:1079] T 45ddd260996746ecbd367a7bbf444fe1 P fa371085a23d4df2b789a40c6cef29d2: Deleting log segment in path: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458671825-13662-0/minicluster-data/ts-0-root/wals/45ddd260996746ecbd367a7bbf444fe1/wal-000000016 (ops 75-78)
I20260812 06:17:47.922847 13953 log.cc:1079] T 45ddd260996746ecbd367a7bbf444fe1 P fa371085a23d4df2b789a40c6cef29d2: Deleting log segment in path: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458671825-13662-0/minicluster-data/ts-0-root/wals/45ddd260996746ecbd367a7bbf444fe1/wal-000000017 (ops 79-83)
I20260812 06:17:47.922904 13953 log.cc:1079] T 45ddd260996746ecbd367a7bbf444fe1 P fa371085a23d4df2b789a40c6cef29d2: Deleting log segment in path: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458671825-13662-0/minicluster-data/ts-0-root/wals/45ddd260996746ecbd367a7bbf444fe1/wal-000000018 (ops 84-88)
I20260812 06:17:47.922955 13953 log.cc:1079] T 45ddd260996746ecbd367a7bbf444fe1 P fa371085a23d4df2b789a40c6cef29d2: Deleting log segment in path: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458671825-13662-0/minicluster-data/ts-0-root/wals/45ddd260996746ecbd367a7bbf444fe1/wal-000000019 (ops 89-92)
I20260812 06:17:47.923007 13953 log.cc:1079] T 45ddd260996746ecbd367a7bbf444fe1 P fa371085a23d4df2b789a40c6cef29d2: Deleting log segment in path: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458671825-13662-0/minicluster-data/ts-0-root/wals/45ddd260996746ecbd367a7bbf444fe1/wal-000000020 (ops 93-97)
I20260812 06:17:47.923059 13953 log.cc:1079] T 45ddd260996746ecbd367a7bbf444fe1 P fa371085a23d4df2b789a40c6cef29d2: Deleting log segment in path: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458671825-13662-0/minicluster-data/ts-0-root/wals/45ddd260996746ecbd367a7bbf444fe1/wal-000000021 (ops 98-102)
I20260812 06:17:47.923111 13953 log.cc:1079] T 45ddd260996746ecbd367a7bbf444fe1 P fa371085a23d4df2b789a40c6cef29d2: Deleting log segment in path: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458671825-13662-0/minicluster-data/ts-0-root/wals/45ddd260996746ecbd367a7bbf444fe1/wal-000000022 (ops 103-107)
I20260812 06:17:47.923164 13953 log.cc:1079] T 45ddd260996746ecbd367a7bbf444fe1 P fa371085a23d4df2b789a40c6cef29d2: Deleting log segment in path: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458671825-13662-0/minicluster-data/ts-0-root/wals/45ddd260996746ecbd367a7bbf444fe1/wal-000000023 (ops 108-112)
I20260812 06:17:47.923220 13953 log.cc:1079] T 45ddd260996746ecbd367a7bbf444fe1 P fa371085a23d4df2b789a40c6cef29d2: Deleting log segment in path: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458671825-13662-0/minicluster-data/ts-0-root/wals/45ddd260996746ecbd367a7bbf444fe1/wal-000000024 (ops 113-117)
I20260812 06:17:47.923276 13953 log.cc:1079] T 45ddd260996746ecbd367a7bbf444fe1 P fa371085a23d4df2b789a40c6cef29d2: Deleting log segment in path: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458671825-13662-0/minicluster-data/ts-0-root/wals/45ddd260996746ecbd367a7bbf444fe1/wal-000000025 (ops 118-122)
I20260812 06:17:47.923328 13953 log.cc:1079] T 45ddd260996746ecbd367a7bbf444fe1 P fa371085a23d4df2b789a40c6cef29d2: Deleting log segment in path: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458671825-13662-0/minicluster-data/ts-0-root/wals/45ddd260996746ecbd367a7bbf444fe1/wal-000000026 (ops 123-127)
I20260812 06:17:47.950301 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: LogGCOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.028s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:17:47.950719 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1): perf score=3.181125
I20260812 06:17:47.965312 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.014s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":5650,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:47.965809 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling UndoDeltaBlockGCOp(45ddd260996746ecbd367a7bbf444fe1): 472 bytes on disk
I20260812 06:17:47.966264 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: UndoDeltaBlockGCOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4}
I20260812 06:17:47.966830 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1): perf score=2.188937
I20260812 06:17:47.979705 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.013s	user 0.005s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4579,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:47.980187 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling MajorDeltaCompactionOp(45ddd260996746ecbd367a7bbf444fe1): perf score=1.000000
I20260812 06:17:48.139878 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: MajorDeltaCompactionOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.159s	user 0.130s	sys 0.028s Metrics: {"cfile_cache_miss":534,"cfile_cache_miss_bytes":24815903,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":537,"lbm_read_time_us":12171,"lbm_reads_lt_1ms":566,"lbm_write_time_us":28339,"lbm_writes_lt_1ms":543,"mutex_wait_us":51,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11136,"thread_start_us":63,"threads_started":1,"update_count":2500}
I20260812 06:17:48.140473 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1): perf score=11.118625
I20260812 06:17:48.178094 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.037s	user 0.019s	sys 0.016s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":16050,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:48.178589 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1): perf score=2.188937
I20260812 06:17:48.193820 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.015s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6205,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":92,"reinsert_count":0,"update_count":450}
I20260812 06:17:48.194310 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling MajorDeltaCompactionOp(45ddd260996746ecbd367a7bbf444fe1): perf score=1.000000
I20260812 06:17:48.329721 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: MajorDeltaCompactionOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.135s	user 0.111s	sys 0.019s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713264,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":294,"lbm_read_time_us":9957,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23179,"lbm_writes_lt_1ms":443,"mutex_wait_us":43,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:17:48.330262 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1): perf score=10.126437
I20260812 06:17:48.375710 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.045s	user 0.029s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14952,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:48.376345 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1): perf score=2.188937
I20260812 06:17:48.388166 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4245,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:48.390008 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling MajorDeltaCompactionOp(45ddd260996746ecbd367a7bbf444fe1): perf score=1.000000
I20260812 06:17:48.556878 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: MajorDeltaCompactionOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.165s	user 0.118s	sys 0.047s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713271,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":305,"lbm_read_time_us":11463,"lbm_reads_lt_1ms":468,"lbm_write_time_us":27562,"lbm_writes_lt_1ms":443,"mutex_wait_us":64,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6656,"update_count":2000}
I20260812 06:17:48.558472 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1): perf score=10.126437
I20260812 06:17:48.595070 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.036s	user 0.022s	sys 0.003s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":11887,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:48.596091 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1): perf score=2.188937
I20260812 06:17:48.611088 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5122,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:48.615238 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling MajorDeltaCompactionOp(45ddd260996746ecbd367a7bbf444fe1): perf score=1.000000
I20260812 06:17:48.758810 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: MajorDeltaCompactionOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.143s	user 0.102s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713273,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":640,"lbm_read_time_us":10228,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25721,"lbm_writes_lt_1ms":443,"mutex_wait_us":261,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":15232,"update_count":2000}
I20260812 06:17:48.759336 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1): perf score=10.126437
I20260812 06:17:48.803784 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.044s	user 0.033s	sys 0.003s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17391,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:48.804194 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1): perf score=2.188937
I20260812 06:17:48.813987 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3592,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:48.814446 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling MajorDeltaCompactionOp(45ddd260996746ecbd367a7bbf444fe1): perf score=1.000000
I20260812 06:17:48.961061 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: MajorDeltaCompactionOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.146s	user 0.118s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713271,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":536,"lbm_read_time_us":9942,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28140,"lbm_writes_lt_1ms":443,"mutex_wait_us":33,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:48.961688 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1): perf score=10.126437
I20260812 06:17:49.003777 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.042s	user 0.027s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17728,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:49.004210 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1): perf score=2.188937
I20260812 06:17:49.013851 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3524,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:49.014261 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling MajorDeltaCompactionOp(45ddd260996746ecbd367a7bbf444fe1): perf score=1.000000
I20260812 06:17:49.146977 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: MajorDeltaCompactionOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.133s	user 0.107s	sys 0.025s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1431,"lbm_read_time_us":9100,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23676,"lbm_writes_lt_1ms":443,"mutex_wait_us":284,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14976,"update_count":2000}
I20260812 06:17:49.147569 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1): perf score=10.126437
I20260812 06:17:49.195675 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.048s	user 0.031s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15213,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:49.196206 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1): perf score=2.188937
I20260812 06:17:49.208863 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.013s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4912,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:49.209285 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling MajorDeltaCompactionOp(45ddd260996746ecbd367a7bbf444fe1): perf score=1.000000
I20260812 06:17:49.368772 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: MajorDeltaCompactionOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.159s	user 0.096s	sys 0.060s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":129,"lbm_read_time_us":10107,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26528,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13312,"update_count":2000}
I20260812 06:17:49.369896 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1): perf score=11.118625
I20260812 06:17:49.416227 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.046s	user 0.034s	sys 0.011s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":19855,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:49.416875 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1): perf score=2.188937
I20260812 06:17:49.441684 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.025s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4020610,"delete_count":0,"lbm_write_time_us":5158,"lbm_writes_lt_1ms":101,"reinsert_count":0,"update_count":490}
I20260812 06:17:49.442222 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1): perf score=2.188937
I20260812 06:17:49.455979 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.014s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3774459,"delete_count":0,"lbm_write_time_us":5301,"lbm_writes_lt_1ms":95,"reinsert_count":0,"update_count":460}
I20260812 06:17:49.456559 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling FlushMRSOp(45ddd260996746ecbd367a7bbf444fe1): perf score=1.000000
I20260812 06:17:49.494163 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: FlushMRSOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.037s	user 0.032s	sys 0.003s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":75,"dirs.run_cpu_time_us":208,"dirs.run_wall_time_us":1131,"drs_written":1,"lbm_read_time_us":97,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2133,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:49.495056 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling LogGCOp(45ddd260996746ecbd367a7bbf444fe1): free 133024647 bytes of WAL
I20260812 06:17:49.495271 13953 log_reader.cc:385] T 45ddd260996746ecbd367a7bbf444fe1: removed 13 log segments from log reader
I20260812 06:17:49.495324 13953 log.cc:1079] T 45ddd260996746ecbd367a7bbf444fe1 P fa371085a23d4df2b789a40c6cef29d2: Deleting log segment in path: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458671825-13662-0/minicluster-data/ts-0-root/wals/45ddd260996746ecbd367a7bbf444fe1/wal-000000027 (ops 128-132)
I20260812 06:17:49.495419 13953 log.cc:1079] T 45ddd260996746ecbd367a7bbf444fe1 P fa371085a23d4df2b789a40c6cef29d2: Deleting log segment in path: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458671825-13662-0/minicluster-data/ts-0-root/wals/45ddd260996746ecbd367a7bbf444fe1/wal-000000028 (ops 133-136)
I20260812 06:17:49.495460 13953 log.cc:1079] T 45ddd260996746ecbd367a7bbf444fe1 P fa371085a23d4df2b789a40c6cef29d2: Deleting log segment in path: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458671825-13662-0/minicluster-data/ts-0-root/wals/45ddd260996746ecbd367a7bbf444fe1/wal-000000029 (ops 137-141)
I20260812 06:17:49.495510 13953 log.cc:1079] T 45ddd260996746ecbd367a7bbf444fe1 P fa371085a23d4df2b789a40c6cef29d2: Deleting log segment in path: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458671825-13662-0/minicluster-data/ts-0-root/wals/45ddd260996746ecbd367a7bbf444fe1/wal-000000030 (ops 142-146)
I20260812 06:17:49.495549 13953 log.cc:1079] T 45ddd260996746ecbd367a7bbf444fe1 P fa371085a23d4df2b789a40c6cef29d2: Deleting log segment in path: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458671825-13662-0/minicluster-data/ts-0-root/wals/45ddd260996746ecbd367a7bbf444fe1/wal-000000031 (ops 147-151)
I20260812 06:17:49.495638 13953 log.cc:1079] T 45ddd260996746ecbd367a7bbf444fe1 P fa371085a23d4df2b789a40c6cef29d2: Deleting log segment in path: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458671825-13662-0/minicluster-data/ts-0-root/wals/45ddd260996746ecbd367a7bbf444fe1/wal-000000032 (ops 152-156)
I20260812 06:17:49.495680 13953 log.cc:1079] T 45ddd260996746ecbd367a7bbf444fe1 P fa371085a23d4df2b789a40c6cef29d2: Deleting log segment in path: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458671825-13662-0/minicluster-data/ts-0-root/wals/45ddd260996746ecbd367a7bbf444fe1/wal-000000033 (ops 157-161)
I20260812 06:17:49.495740 13953 log.cc:1079] T 45ddd260996746ecbd367a7bbf444fe1 P fa371085a23d4df2b789a40c6cef29d2: Deleting log segment in path: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458671825-13662-0/minicluster-data/ts-0-root/wals/45ddd260996746ecbd367a7bbf444fe1/wal-000000034 (ops 162-166)
I20260812 06:17:49.495779 13953 log.cc:1079] T 45ddd260996746ecbd367a7bbf444fe1 P fa371085a23d4df2b789a40c6cef29d2: Deleting log segment in path: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458671825-13662-0/minicluster-data/ts-0-root/wals/45ddd260996746ecbd367a7bbf444fe1/wal-000000035 (ops 167-171)
I20260812 06:17:49.495839 13953 log.cc:1079] T 45ddd260996746ecbd367a7bbf444fe1 P fa371085a23d4df2b789a40c6cef29d2: Deleting log segment in path: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458671825-13662-0/minicluster-data/ts-0-root/wals/45ddd260996746ecbd367a7bbf444fe1/wal-000000036 (ops 172-176)
I20260812 06:17:49.495877 13953 log.cc:1079] T 45ddd260996746ecbd367a7bbf444fe1 P fa371085a23d4df2b789a40c6cef29d2: Deleting log segment in path: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458671825-13662-0/minicluster-data/ts-0-root/wals/45ddd260996746ecbd367a7bbf444fe1/wal-000000037 (ops 177-181)
I20260812 06:17:49.495935 13953 log.cc:1079] T 45ddd260996746ecbd367a7bbf444fe1 P fa371085a23d4df2b789a40c6cef29d2: Deleting log segment in path: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458671825-13662-0/minicluster-data/ts-0-root/wals/45ddd260996746ecbd367a7bbf444fe1/wal-000000038 (ops 182-186)
I20260812 06:17:49.495975 13953 log.cc:1079] T 45ddd260996746ecbd367a7bbf444fe1 P fa371085a23d4df2b789a40c6cef29d2: Deleting log segment in path: /tmp/dist-test-taskNZ5Eny/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458671825-13662-0/minicluster-data/ts-0-root/wals/45ddd260996746ecbd367a7bbf444fe1/wal-000000039 (ops 187-191)
I20260812 06:17:49.523572 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: LogGCOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.028s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:17:49.524794 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1): perf score=3.181125
I20260812 06:17:49.543627 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.019s	user 0.008s	sys 0.008s Metrics: {"bytes_written":5374416,"delete_count":0,"lbm_write_time_us":7791,"lbm_writes_lt_1ms":134,"reinsert_count":0,"update_count":655}
I20260812 06:17:49.544132 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling UndoDeltaBlockGCOp(45ddd260996746ecbd367a7bbf444fe1): 483 bytes on disk
I20260812 06:17:49.544589 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: UndoDeltaBlockGCOp(45ddd260996746ecbd367a7bbf444fe1) 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:17:49.545258 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1): perf score=1.196750
I20260812 06:17:49.563247 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: FlushDeltaMemStoresOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.018s	user 0.005s	sys 0.004s Metrics: {"bytes_written":2830880,"delete_count":0,"lbm_write_time_us":4016,"lbm_writes_lt_1ms":72,"reinsert_count":0,"update_count":345}
I20260812 06:17:49.563799 14013 maintenance_manager.cc:419] P fa371085a23d4df2b789a40c6cef29d2: Scheduling MajorDeltaCompactionOp(45ddd260996746ecbd367a7bbf444fe1): perf score=1.000000
I20260812 06:17:49.715093 13662 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.032s	user 1.752s	sys 0.148s
I20260812 06:17:49.807108 13662 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.092s	user 0.000s	sys 0.000s
I20260812 06:17:49.807521 13662 tablet_server.cc:179] TabletServer@127.13.87.129:0 shutting down...
I20260812 06:17:49.823639 13953 maintenance_manager.cc:643] P fa371085a23d4df2b789a40c6cef29d2: MajorDeltaCompactionOp(45ddd260996746ecbd367a7bbf444fe1) complete. Timing: real 0.260s	user 0.174s	sys 0.085s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":33020833,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":156,"lbm_read_time_us":17559,"lbm_reads_lt_1ms":763,"lbm_write_time_us":45111,"lbm_writes_lt_1ms":743,"mutex_wait_us":63,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":35584,"thread_start_us":91,"threads_started":1,"update_count":3500}
I20260812 06:17:49.825210 13662 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:49.825618 13662 tablet_replica.cc:333] T 45ddd260996746ecbd367a7bbf444fe1 P fa371085a23d4df2b789a40c6cef29d2: stopping tablet replica
I20260812 06:17:49.825750 13662 raft_consensus.cc:2243] T 45ddd260996746ecbd367a7bbf444fe1 P fa371085a23d4df2b789a40c6cef29d2 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:49.825914 13662 raft_consensus.cc:2272] T 45ddd260996746ecbd367a7bbf444fe1 P fa371085a23d4df2b789a40c6cef29d2 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:49.842697 13662 tablet_server.cc:196] TabletServer@127.13.87.129:0 shutdown complete.
I20260812 06:17:49.880712 13662 master.cc:562] Master@127.13.87.190:42339 shutting down...
I20260812 06:17:49.884588 13662 raft_consensus.cc:2243] T 00000000000000000000000000000000 P ae1b991d0c1242ab97afc1f181832ae6 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:49.884770 13662 raft_consensus.cc:2272] T 00000000000000000000000000000000 P ae1b991d0c1242ab97afc1f181832ae6 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:49.884851 13662 tablet_replica.cc:333] T 00000000000000000000000000000000 P ae1b991d0c1242ab97afc1f181832ae6: stopping tablet replica
I20260812 06:17:49.896906 13662 master.cc:584] Master@127.13.87.190:42339 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5499 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11310 ms total)

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