[==========] 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:16:52.921630 14797 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.14.115.126:39555
I20260812 06:16:52.922796 14797 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:16:52.923435 14797 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:52.929852 14814 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:16:52.929819 14806 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:16:52.930120 14811 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:16:52.930205 14797 server_base.cc:1061] running on GCE node
I20260812 06:16:52.930737 14797 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:52.930833 14797 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:16:52.930864 14797 hybrid_clock.cc:648] HybridClock initialized: now 1786515412930862 us; error 0 us; skew 500 ppm
I20260812 06:16:52.932708 14797 webserver.cc:533] Webserver started at http://127.14.115.126:36253/ using document root <none> and password file <none>
I20260812 06:16:52.933236 14797 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:52.933295 14797 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:52.933488 14797 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:52.935223 14797 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412910501-14797-0/minicluster-data/master-0-root/instance:
uuid: "7dac6e995a4d48c0aa8a0866eb285441"
format_stamp: "Formatted at 2026-08-12 06:16:52 on dist-test-slave-jztv"
I20260812 06:16:52.938740 14797 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.003s	sys 0.001s
I20260812 06:16:52.940809 14821 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:16:52.941968 14797 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:16:52.942101 14797 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412910501-14797-0/minicluster-data/master-0-root
uuid: "7dac6e995a4d48c0aa8a0866eb285441"
format_stamp: "Formatted at 2026-08-12 06:16:52 on dist-test-slave-jztv"
I20260812 06:16:52.942253 14797 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412910501-14797-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412910501-14797-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412910501-14797-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:16:52.968962 14797 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:52.969637 14797 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:16:52.969832 14797 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:52.977762 14797 rpc_server.cc:307] RPC server started. Bound to: 127.14.115.126:39555
I20260812 06:16:52.977771 14912 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.14.115.126:39555 every 8 connection(s)
I20260812 06:16:52.980046 14913 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:16:52.985420 14913 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 7dac6e995a4d48c0aa8a0866eb285441: Bootstrap starting.
I20260812 06:16:52.987800 14913 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 7dac6e995a4d48c0aa8a0866eb285441: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:52.988714 14913 log.cc:826] T 00000000000000000000000000000000 P 7dac6e995a4d48c0aa8a0866eb285441: Log is configured to *not* fsync() on all Append() calls
I20260812 06:16:52.990382 14913 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 7dac6e995a4d48c0aa8a0866eb285441: No bootstrap required, opened a new log
I20260812 06:16:52.993098 14913 raft_consensus.cc:359] T 00000000000000000000000000000000 P 7dac6e995a4d48c0aa8a0866eb285441 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7dac6e995a4d48c0aa8a0866eb285441" member_type: VOTER }
I20260812 06:16:52.993265 14913 raft_consensus.cc:385] T 00000000000000000000000000000000 P 7dac6e995a4d48c0aa8a0866eb285441 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:52.993398 14913 raft_consensus.cc:740] T 00000000000000000000000000000000 P 7dac6e995a4d48c0aa8a0866eb285441 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 7dac6e995a4d48c0aa8a0866eb285441, State: Initialized, Role: FOLLOWER
I20260812 06:16:52.993995 14913 consensus_queue.cc:260] T 00000000000000000000000000000000 P 7dac6e995a4d48c0aa8a0866eb285441 [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: "7dac6e995a4d48c0aa8a0866eb285441" member_type: VOTER }
I20260812 06:16:52.994161 14913 raft_consensus.cc:399] T 00000000000000000000000000000000 P 7dac6e995a4d48c0aa8a0866eb285441 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:52.994271 14913 raft_consensus.cc:493] T 00000000000000000000000000000000 P 7dac6e995a4d48c0aa8a0866eb285441 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:52.994417 14913 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 7dac6e995a4d48c0aa8a0866eb285441 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:52.995234 14913 raft_consensus.cc:515] T 00000000000000000000000000000000 P 7dac6e995a4d48c0aa8a0866eb285441 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7dac6e995a4d48c0aa8a0866eb285441" member_type: VOTER }
I20260812 06:16:52.995687 14913 leader_election.cc:304] T 00000000000000000000000000000000 P 7dac6e995a4d48c0aa8a0866eb285441 [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: 7dac6e995a4d48c0aa8a0866eb285441; no voters: 
I20260812 06:16:52.996021 14913 leader_election.cc:290] T 00000000000000000000000000000000 P 7dac6e995a4d48c0aa8a0866eb285441 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:52.996124 14919 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 7dac6e995a4d48c0aa8a0866eb285441 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:52.996403 14919 raft_consensus.cc:697] T 00000000000000000000000000000000 P 7dac6e995a4d48c0aa8a0866eb285441 [term 1 LEADER]: Becoming Leader. State: Replica: 7dac6e995a4d48c0aa8a0866eb285441, State: Running, Role: LEADER
I20260812 06:16:52.996819 14919 consensus_queue.cc:237] T 00000000000000000000000000000000 P 7dac6e995a4d48c0aa8a0866eb285441 [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: "7dac6e995a4d48c0aa8a0866eb285441" member_type: VOTER }
I20260812 06:16:52.997069 14913 sys_catalog.cc:565] T 00000000000000000000000000000000 P 7dac6e995a4d48c0aa8a0866eb285441 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:52.998574 14920 sys_catalog.cc:455] T 00000000000000000000000000000000 P 7dac6e995a4d48c0aa8a0866eb285441 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "7dac6e995a4d48c0aa8a0866eb285441" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7dac6e995a4d48c0aa8a0866eb285441" member_type: VOTER } }
I20260812 06:16:52.998746 14920 sys_catalog.cc:458] T 00000000000000000000000000000000 P 7dac6e995a4d48c0aa8a0866eb285441 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:52.998849 14923 sys_catalog.cc:455] T 00000000000000000000000000000000 P 7dac6e995a4d48c0aa8a0866eb285441 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 7dac6e995a4d48c0aa8a0866eb285441. Latest consensus state: current_term: 1 leader_uuid: "7dac6e995a4d48c0aa8a0866eb285441" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7dac6e995a4d48c0aa8a0866eb285441" member_type: VOTER } }
I20260812 06:16:52.998957 14923 sys_catalog.cc:458] T 00000000000000000000000000000000 P 7dac6e995a4d48c0aa8a0866eb285441 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:52.999577 14797 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:16:53.001587 14946 catalog_manager.cc:1594] T 00000000000000000000000000000000 P 7dac6e995a4d48c0aa8a0866eb285441: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:16:53.001652 14946 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:16:53.001746 14939 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:53.002552 14939 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:53.007045 14939 catalog_manager.cc:1383] Generated new cluster ID: f9700194fb9641f5a9d6a53ff04931f7
I20260812 06:16:53.007108 14939 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:53.017452 14939 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:53.018406 14939 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:53.023736 14939 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 7dac6e995a4d48c0aa8a0866eb285441: Generated new TSK 0
I20260812 06:16:53.024333 14939 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:53.032464 14797 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:53.035431 14954 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:16:53.035537 14955 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:16:53.035588 14959 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:16:53.035739 14797 server_base.cc:1061] running on GCE node
I20260812 06:16:53.036043 14797 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:53.036087 14797 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:16:53.036104 14797 hybrid_clock.cc:648] HybridClock initialized: now 1786515413036104 us; error 0 us; skew 500 ppm
I20260812 06:16:53.037024 14797 webserver.cc:533] Webserver started at http://127.14.115.65:33873/ using document root <none> and password file <none>
I20260812 06:16:53.037210 14797 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:53.037258 14797 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:53.037358 14797 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:53.037748 14797 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412910501-14797-0/minicluster-data/ts-0-root/instance:
uuid: "a4b9b25a8d9548f1991eeab6cb232fa8"
format_stamp: "Formatted at 2026-08-12 06:16:53 on dist-test-slave-jztv"
I20260812 06:16:53.039386 14797 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:16:53.040429 14971 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:16:53.040730 14797 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:16:53.040823 14797 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412910501-14797-0/minicluster-data/ts-0-root
uuid: "a4b9b25a8d9548f1991eeab6cb232fa8"
format_stamp: "Formatted at 2026-08-12 06:16:53 on dist-test-slave-jztv"
I20260812 06:16:53.040918 14797 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412910501-14797-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412910501-14797-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412910501-14797-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:16:53.045872 14797 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:53.046334 14797 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:53.046892 14797 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:53.047763 14797 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:53.047837 14797 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:53.047915 14797 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:53.047958 14797 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:53.055177 14797 rpc_server.cc:307] RPC server started. Bound to: 127.14.115.65:45617
I20260812 06:16:53.055212 15091 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.14.115.65:45617 every 8 connection(s)
I20260812 06:16:53.069358 15092 heartbeater.cc:344] Connected to a master server at 127.14.115.126:39555
I20260812 06:16:53.069654 15092 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:53.070102 15092 heartbeater.cc:507] Master 127.14.115.126:39555 requested a full tablet report, sending...
I20260812 06:16:53.071568 14854 ts_manager.cc:194] Registered new tserver with Master: a4b9b25a8d9548f1991eeab6cb232fa8 (127.14.115.65:45617)
I20260812 06:16:53.071676 14797 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.01580396s
I20260812 06:16:53.073582 14854 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:46360
I20260812 06:16:53.081465 14854 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:46374:
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:16:53.095870 15030 tablet_service.cc:1511] Processing CreateTablet for tablet ed130596693f481981c6f93d643732c8 (DEFAULT_TABLE table=heavy-update-compaction-test [id=5083536386584d4688e6929102600f51]), partition=
I20260812 06:16:53.096427 15030 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet ed130596693f481981c6f93d643732c8. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:53.098902 15112 tablet_bootstrap.cc:492] T ed130596693f481981c6f93d643732c8 P a4b9b25a8d9548f1991eeab6cb232fa8: Bootstrap starting.
I20260812 06:16:53.100059 15112 tablet_bootstrap.cc:654] T ed130596693f481981c6f93d643732c8 P a4b9b25a8d9548f1991eeab6cb232fa8: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:53.101404 15112 tablet_bootstrap.cc:492] T ed130596693f481981c6f93d643732c8 P a4b9b25a8d9548f1991eeab6cb232fa8: No bootstrap required, opened a new log
I20260812 06:16:53.101526 15112 ts_tablet_manager.cc:1403] T ed130596693f481981c6f93d643732c8 P a4b9b25a8d9548f1991eeab6cb232fa8: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:16:53.102008 15112 raft_consensus.cc:359] T ed130596693f481981c6f93d643732c8 P a4b9b25a8d9548f1991eeab6cb232fa8 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a4b9b25a8d9548f1991eeab6cb232fa8" member_type: VOTER last_known_addr { host: "127.14.115.65" port: 45617 } }
I20260812 06:16:53.102136 15112 raft_consensus.cc:385] T ed130596693f481981c6f93d643732c8 P a4b9b25a8d9548f1991eeab6cb232fa8 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:53.102171 15112 raft_consensus.cc:740] T ed130596693f481981c6f93d643732c8 P a4b9b25a8d9548f1991eeab6cb232fa8 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: a4b9b25a8d9548f1991eeab6cb232fa8, State: Initialized, Role: FOLLOWER
I20260812 06:16:53.102346 15112 consensus_queue.cc:260] T ed130596693f481981c6f93d643732c8 P a4b9b25a8d9548f1991eeab6cb232fa8 [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: "a4b9b25a8d9548f1991eeab6cb232fa8" member_type: VOTER last_known_addr { host: "127.14.115.65" port: 45617 } }
I20260812 06:16:53.102481 15112 raft_consensus.cc:399] T ed130596693f481981c6f93d643732c8 P a4b9b25a8d9548f1991eeab6cb232fa8 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:53.102520 15112 raft_consensus.cc:493] T ed130596693f481981c6f93d643732c8 P a4b9b25a8d9548f1991eeab6cb232fa8 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:53.102562 15112 raft_consensus.cc:3060] T ed130596693f481981c6f93d643732c8 P a4b9b25a8d9548f1991eeab6cb232fa8 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:53.103502 15112 raft_consensus.cc:515] T ed130596693f481981c6f93d643732c8 P a4b9b25a8d9548f1991eeab6cb232fa8 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a4b9b25a8d9548f1991eeab6cb232fa8" member_type: VOTER last_known_addr { host: "127.14.115.65" port: 45617 } }
I20260812 06:16:53.103693 15112 leader_election.cc:304] T ed130596693f481981c6f93d643732c8 P a4b9b25a8d9548f1991eeab6cb232fa8 [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: a4b9b25a8d9548f1991eeab6cb232fa8; no voters: 
I20260812 06:16:53.103909 15112 leader_election.cc:290] T ed130596693f481981c6f93d643732c8 P a4b9b25a8d9548f1991eeab6cb232fa8 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:53.104085 15116 raft_consensus.cc:2804] T ed130596693f481981c6f93d643732c8 P a4b9b25a8d9548f1991eeab6cb232fa8 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:53.104226 15112 ts_tablet_manager.cc:1434] T ed130596693f481981c6f93d643732c8 P a4b9b25a8d9548f1991eeab6cb232fa8: Time spent starting tablet: real 0.003s	user 0.000s	sys 0.003s
I20260812 06:16:53.104347 15116 raft_consensus.cc:697] T ed130596693f481981c6f93d643732c8 P a4b9b25a8d9548f1991eeab6cb232fa8 [term 1 LEADER]: Becoming Leader. State: Replica: a4b9b25a8d9548f1991eeab6cb232fa8, State: Running, Role: LEADER
I20260812 06:16:53.104522 15092 heartbeater.cc:499] Master 127.14.115.126:39555 was elected leader, sending a full tablet report...
I20260812 06:16:53.104604 15116 consensus_queue.cc:237] T ed130596693f481981c6f93d643732c8 P a4b9b25a8d9548f1991eeab6cb232fa8 [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: "a4b9b25a8d9548f1991eeab6cb232fa8" member_type: VOTER last_known_addr { host: "127.14.115.65" port: 45617 } }
I20260812 06:16:53.107407 14854 catalog_manager.cc:5719] T ed130596693f481981c6f93d643732c8 P a4b9b25a8d9548f1991eeab6cb232fa8 reported cstate change: term changed from 0 to 1, leader changed from <none> to a4b9b25a8d9548f1991eeab6cb232fa8 (127.14.115.65). New cstate: current_term: 1 leader_uuid: "a4b9b25a8d9548f1991eeab6cb232fa8" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a4b9b25a8d9548f1991eeab6cb232fa8" member_type: VOTER last_known_addr { host: "127.14.115.65" port: 45617 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:53.174510 14797 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.058s	user 0.011s	sys 0.015s
I20260812 06:16:53.306427 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling FlushMRSOp(ed130596693f481981c6f93d643732c8): perf score=15.086190
I20260812 06:16:53.463125 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: FlushMRSOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.156s	user 0.107s	sys 0.048s Metrics: {"bytes_written":11897249,"cfile_init":1,"compiler_manager_pool.queue_time_us":221,"delete_count":0,"dirs.queue_time_us":73,"dirs.run_cpu_time_us":212,"dirs.run_wall_time_us":974,"drs_written":1,"lbm_read_time_us":76,"lbm_reads_lt_1ms":4,"lbm_write_time_us":40144,"lbm_writes_lt_1ms":657,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":113,"threads_started":1,"update_count":1450}
I20260812 06:16:53.464284 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling LogGCOp(ed130596693f481981c6f93d643732c8): free 20743880 bytes of WAL
I20260812 06:16:53.464600 14979 log_reader.cc:385] T ed130596693f481981c6f93d643732c8: removed 2 log segments from log reader
I20260812 06:16:53.464668 14979 log.cc:1079] T ed130596693f481981c6f93d643732c8 P a4b9b25a8d9548f1991eeab6cb232fa8: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/ed130596693f481981c6f93d643732c8/wal-000000001 (ops 1-6)
I20260812 06:16:53.464721 14979 log.cc:1079] T ed130596693f481981c6f93d643732c8 P a4b9b25a8d9548f1991eeab6cb232fa8: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/ed130596693f481981c6f93d643732c8/wal-000000002 (ops 7-11)
I20260812 06:16:53.470053 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: LogGCOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.006s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:16:53.470427 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling UndoDeltaBlockGCOp(ed130596693f481981c6f93d643732c8): 12719216 bytes on disk
I20260812 06:16:53.471067 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: UndoDeltaBlockGCOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":71,"lbm_reads_lt_1ms":4}
I20260812 06:16:53.471467 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8): perf score=2.188937
I20260812 06:16:53.490149 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.019s	user 0.009s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6396,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:53.490671 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling MajorDeltaCompactionOp(ed130596693f481981c6f93d643732c8): perf score=1.000000
I20260812 06:16:53.616979 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: MajorDeltaCompactionOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.126s	user 0.098s	sys 0.028s Metrics: {"cfile_cache_miss":422,"cfile_cache_miss_bytes":20262036,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":549,"lbm_read_time_us":7217,"lbm_reads_lt_1ms":454,"lbm_write_time_us":23572,"lbm_writes_lt_1ms":433,"peak_mem_usage":49238594,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":307,"threads_started":5,"update_count":1950}
I20260812 06:16:53.617605 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8): perf score=10.126437
I20260812 06:16:53.663686 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.046s	user 0.033s	sys 0.000s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":14570,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:53.664126 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8): perf score=2.188937
I20260812 06:16:53.675009 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3905,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:53.675604 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling MajorDeltaCompactionOp(ed130596693f481981c6f93d643732c8): perf score=1.000000
I20260812 06:16:53.798386 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: MajorDeltaCompactionOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.123s	user 0.094s	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":1314,"lbm_read_time_us":7763,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24568,"lbm_writes_lt_1ms":443,"mutex_wait_us":388,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:16:53.798936 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8): perf score=10.126437
I20260812 06:16:53.843912 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.045s	user 0.014s	sys 0.020s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15486,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:53.844465 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8): perf score=2.188937
I20260812 06:16:53.855383 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.011s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4018,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:53.855937 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling MajorDeltaCompactionOp(ed130596693f481981c6f93d643732c8): perf score=1.000000
I20260812 06:16:53.975986 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: MajorDeltaCompactionOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.120s	user 0.100s	sys 0.018s 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":314,"lbm_read_time_us":9099,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22177,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2000}
I20260812 06:16:53.976584 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8): perf score=10.126437
I20260812 06:16:54.023752 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.047s	user 0.016s	sys 0.026s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14670,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:54.024371 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8): perf score=2.188937
I20260812 06:16:54.040680 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.016s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6022,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:54.041277 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling MajorDeltaCompactionOp(ed130596693f481981c6f93d643732c8): perf score=1.000000
I20260812 06:16:54.182971 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: MajorDeltaCompactionOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.141s	user 0.098s	sys 0.043s 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":627,"lbm_read_time_us":10740,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22415,"lbm_writes_lt_1ms":443,"mutex_wait_us":283,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8448,"update_count":2000}
I20260812 06:16:54.183655 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8): perf score=10.126437
I20260812 06:16:54.227567 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.044s	user 0.026s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15155,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:54.228206 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8): perf score=2.188937
I20260812 06:16:54.239131 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4187,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:54.239729 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling MajorDeltaCompactionOp(ed130596693f481981c6f93d643732c8): perf score=1.000000
I20260812 06:16:54.370700 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: MajorDeltaCompactionOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.131s	user 0.101s	sys 0.029s 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":298,"lbm_read_time_us":8650,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27523,"lbm_writes_lt_1ms":443,"mutex_wait_us":53,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12032,"update_count":2000}
I20260812 06:16:54.371337 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8): perf score=10.126437
I20260812 06:16:54.421160 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.050s	user 0.013s	sys 0.020s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15425,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:54.421674 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8): perf score=2.188937
I20260812 06:16:54.433060 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4216,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:54.433672 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling MajorDeltaCompactionOp(ed130596693f481981c6f93d643732c8): perf score=1.000000
I20260812 06:16:54.559392 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: MajorDeltaCompactionOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.125s	user 0.109s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672275,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":159,"lbm_read_time_us":8036,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25361,"lbm_writes_lt_1ms":443,"mutex_wait_us":75,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:16:54.560106 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8): perf score=10.126437
I20260812 06:16:54.612255 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.052s	user 0.031s	sys 0.019s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":22472,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:16:54.612808 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8): perf score=2.188937
I20260812 06:16:54.623538 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4119,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:54.624006 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling MajorDeltaCompactionOp(ed130596693f481981c6f93d643732c8): perf score=1.000000
I20260812 06:16:54.785492 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: MajorDeltaCompactionOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.161s	user 0.105s	sys 0.049s 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":544,"lbm_read_time_us":10545,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26802,"lbm_writes_lt_1ms":443,"mutex_wait_us":64,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":18304,"update_count":2000}
I20260812 06:16:54.786437 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8): perf score=10.126437
I20260812 06:16:54.835312 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.049s	user 0.029s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17499,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:54.835806 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8): perf score=2.188937
I20260812 06:16:54.848686 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.013s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4671,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:54.849256 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling FlushMRSOp(ed130596693f481981c6f93d643732c8): perf score=1.000000
I20260812 06:16:54.885099 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: FlushMRSOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.036s	user 0.034s	sys 0.000s Metrics: {"bytes_written":1275443,"cfile_init":1,"dirs.queue_time_us":76,"dirs.run_cpu_time_us":394,"dirs.run_wall_time_us":1862,"drs_written":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1577,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:16:54.885951 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling LogGCOp(ed130596693f481981c6f93d643732c8): free 120553329 bytes of WAL
I20260812 06:16:54.886181 14979 log_reader.cc:385] T ed130596693f481981c6f93d643732c8: removed 12 log segments from log reader
I20260812 06:16:54.886269 14979 log.cc:1079] T ed130596693f481981c6f93d643732c8 P a4b9b25a8d9548f1991eeab6cb232fa8: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/ed130596693f481981c6f93d643732c8/wal-000000003 (ops 12-16)
I20260812 06:16:54.886343 14979 log.cc:1079] T ed130596693f481981c6f93d643732c8 P a4b9b25a8d9548f1991eeab6cb232fa8: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/ed130596693f481981c6f93d643732c8/wal-000000004 (ops 17-21)
I20260812 06:16:54.886381 14979 log.cc:1079] T ed130596693f481981c6f93d643732c8 P a4b9b25a8d9548f1991eeab6cb232fa8: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/ed130596693f481981c6f93d643732c8/wal-000000005 (ops 22-26)
I20260812 06:16:54.886430 14979 log.cc:1079] T ed130596693f481981c6f93d643732c8 P a4b9b25a8d9548f1991eeab6cb232fa8: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/ed130596693f481981c6f93d643732c8/wal-000000006 (ops 27-31)
I20260812 06:16:54.886468 14979 log.cc:1079] T ed130596693f481981c6f93d643732c8 P a4b9b25a8d9548f1991eeab6cb232fa8: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/ed130596693f481981c6f93d643732c8/wal-000000007 (ops 32-36)
I20260812 06:16:54.886505 14979 log.cc:1079] T ed130596693f481981c6f93d643732c8 P a4b9b25a8d9548f1991eeab6cb232fa8: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/ed130596693f481981c6f93d643732c8/wal-000000008 (ops 37-40)
I20260812 06:16:54.886541 14979 log.cc:1079] T ed130596693f481981c6f93d643732c8 P a4b9b25a8d9548f1991eeab6cb232fa8: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/ed130596693f481981c6f93d643732c8/wal-000000009 (ops 41-45)
I20260812 06:16:54.886579 14979 log.cc:1079] T ed130596693f481981c6f93d643732c8 P a4b9b25a8d9548f1991eeab6cb232fa8: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/ed130596693f481981c6f93d643732c8/wal-000000010 (ops 46-50)
I20260812 06:16:54.886615 14979 log.cc:1079] T ed130596693f481981c6f93d643732c8 P a4b9b25a8d9548f1991eeab6cb232fa8: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/ed130596693f481981c6f93d643732c8/wal-000000011 (ops 51-55)
I20260812 06:16:54.886651 14979 log.cc:1079] T ed130596693f481981c6f93d643732c8 P a4b9b25a8d9548f1991eeab6cb232fa8: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/ed130596693f481981c6f93d643732c8/wal-000000012 (ops 56-60)
I20260812 06:16:54.886687 14979 log.cc:1079] T ed130596693f481981c6f93d643732c8 P a4b9b25a8d9548f1991eeab6cb232fa8: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/ed130596693f481981c6f93d643732c8/wal-000000013 (ops 61-64)
I20260812 06:16:54.886724 14979 log.cc:1079] T ed130596693f481981c6f93d643732c8 P a4b9b25a8d9548f1991eeab6cb232fa8: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/ed130596693f481981c6f93d643732c8/wal-000000014 (ops 65-69)
I20260812 06:16:54.913470 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: LogGCOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.027s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:16:54.914057 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8): perf score=5.165500
I20260812 06:16:54.939535 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.025s	user 0.012s	sys 0.012s Metrics: {"bytes_written":6933327,"delete_count":0,"lbm_write_time_us":6671,"lbm_writes_lt_1ms":172,"reinsert_count":0,"update_count":845}
I20260812 06:16:54.940145 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling LogGCOp(ed130596693f481981c6f93d643732c8): free 12017983 bytes of WAL
I20260812 06:16:54.940454 14979 log_reader.cc:385] T ed130596693f481981c6f93d643732c8: removed 1 log segments from log reader
I20260812 06:16:54.940531 14979 log.cc:1079] T ed130596693f481981c6f93d643732c8 P a4b9b25a8d9548f1991eeab6cb232fa8: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/ed130596693f481981c6f93d643732c8/wal-000000015 (ops 70-74)
I20260812 06:16:54.944044 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: LogGCOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.004s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:16:54.944507 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling UndoDeltaBlockGCOp(ed130596693f481981c6f93d643732c8): 482 bytes on disk
I20260812 06:16:54.946750 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: UndoDeltaBlockGCOp(ed130596693f481981c6f93d643732c8) 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:16:54.947461 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8): perf score=1.000000
I20260812 06:16:54.954043 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.006s	user 0.005s	sys 0.000s Metrics: {"bytes_written":1271927,"delete_count":0,"lbm_write_time_us":2059,"lbm_writes_lt_1ms":34,"reinsert_count":0,"update_count":155}
I20260812 06:16:54.954535 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling MajorDeltaCompactionOp(ed130596693f481981c6f93d643732c8): perf score=1.000000
I20260812 06:16:55.145175 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: MajorDeltaCompactionOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.190s	user 0.117s	sys 0.072s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877270,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1249,"lbm_read_time_us":11482,"lbm_reads_lt_1ms":670,"lbm_write_time_us":33908,"lbm_writes_lt_1ms":643,"mutex_wait_us":758,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":17920,"thread_start_us":83,"threads_started":1,"update_count":3000}
I20260812 06:16:55.145856 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8): perf score=14.095187
I20260812 06:16:55.206187 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.060s	user 0.027s	sys 0.029s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21549,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:55.206928 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8): perf score=2.188937
I20260812 06:16:55.231220 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.024s	user 0.009s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5797,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:55.231822 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8): perf score=2.188937
I20260812 06:16:55.248625 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.017s	user 0.014s	sys 0.001s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6362,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:55.249380 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling MajorDeltaCompactionOp(ed130596693f481981c6f93d643732c8): perf score=1.000000
I20260812 06:16:55.441026 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: MajorDeltaCompactionOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.191s	user 0.127s	sys 0.064s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877219,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":414,"lbm_read_time_us":15853,"lbm_reads_lt_1ms":673,"lbm_write_time_us":31231,"lbm_writes_lt_1ms":643,"mutex_wait_us":61,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":3000}
I20260812 06:16:55.441581 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8): perf score=14.095187
I20260812 06:16:55.497051 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.055s	user 0.027s	sys 0.023s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":25271,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:16:55.497527 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8): perf score=2.188937
I20260812 06:16:55.508148 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4192,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:55.508631 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling MajorDeltaCompactionOp(ed130596693f481981c6f93d643732c8): perf score=1.000000
I20260812 06:16:55.693271 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: MajorDeltaCompactionOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.184s	user 0.125s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":3979,"dirs.run_cpu_time_us":525,"dirs.run_wall_time_us":2750,"lbm_read_time_us":11492,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30976,"lbm_writes_lt_1ms":543,"mutex_wait_us":3138,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13312,"update_count":2500}
I20260812 06:16:55.693806 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8): perf score=14.095187
I20260812 06:16:55.751129 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.057s	user 0.037s	sys 0.015s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19933,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:55.751708 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8): perf score=2.188937
I20260812 06:16:55.762600 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4170,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:55.763208 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling MajorDeltaCompactionOp(ed130596693f481981c6f93d643732c8): perf score=1.000000
I20260812 06:16:55.932898 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: MajorDeltaCompactionOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.169s	user 0.110s	sys 0.059s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1155,"lbm_read_time_us":12207,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30483,"lbm_writes_lt_1ms":543,"mutex_wait_us":239,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5248,"update_count":2500}
I20260812 06:16:55.933491 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8): perf score=10.126437
I20260812 06:16:55.966459 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.033s	user 0.020s	sys 0.012s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14438,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:55.966981 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8): perf score=2.188937
I20260812 06:16:55.980345 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.013s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4926,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:55.980768 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling MajorDeltaCompactionOp(ed130596693f481981c6f93d643732c8): perf score=1.000000
I20260812 06:16:56.128638 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: MajorDeltaCompactionOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.148s	user 0.098s	sys 0.049s 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":191,"lbm_read_time_us":10990,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24901,"lbm_writes_lt_1ms":443,"mutex_wait_us":43,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":15616,"update_count":2000}
I20260812 06:16:56.129375 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8): perf score=10.126437
I20260812 06:16:56.170360 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.041s	user 0.029s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18047,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:56.170845 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8): perf score=2.188937
I20260812 06:16:56.182287 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.011s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3968,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:56.182854 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling MajorDeltaCompactionOp(ed130596693f481981c6f93d643732c8): perf score=1.000000
I20260812 06:16:56.323244 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: MajorDeltaCompactionOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.140s	user 0.108s	sys 0.032s 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":273,"lbm_read_time_us":8837,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26360,"lbm_writes_lt_1ms":443,"mutex_wait_us":43,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":15232,"update_count":2000}
I20260812 06:16:56.324033 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8): perf score=10.126437
I20260812 06:16:56.367609 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.043s	user 0.027s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16054,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:56.368095 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8): perf score=2.188937
I20260812 06:16:56.378847 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.011s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4089,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:56.379374 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling FlushMRSOp(ed130596693f481981c6f93d643732c8): perf score=1.000000
I20260812 06:16:56.414300 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: FlushMRSOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.035s	user 0.034s	sys 0.000s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":89,"dirs.run_cpu_time_us":217,"dirs.run_wall_time_us":1380,"drs_written":1,"lbm_read_time_us":65,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2057,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:16:56.415005 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling LogGCOp(ed130596693f481981c6f93d643732c8): free 121006461 bytes of WAL
I20260812 06:16:56.415234 14979 log_reader.cc:385] T ed130596693f481981c6f93d643732c8: removed 12 log segments from log reader
I20260812 06:16:56.415282 14979 log.cc:1079] T ed130596693f481981c6f93d643732c8 P a4b9b25a8d9548f1991eeab6cb232fa8: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/ed130596693f481981c6f93d643732c8/wal-000000016 (ops 75-79)
I20260812 06:16:56.415313 14979 log.cc:1079] T ed130596693f481981c6f93d643732c8 P a4b9b25a8d9548f1991eeab6cb232fa8: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/ed130596693f481981c6f93d643732c8/wal-000000017 (ops 80-84)
I20260812 06:16:56.415376 14979 log.cc:1079] T ed130596693f481981c6f93d643732c8 P a4b9b25a8d9548f1991eeab6cb232fa8: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/ed130596693f481981c6f93d643732c8/wal-000000018 (ops 85-88)
I20260812 06:16:56.415431 14979 log.cc:1079] T ed130596693f481981c6f93d643732c8 P a4b9b25a8d9548f1991eeab6cb232fa8: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/ed130596693f481981c6f93d643732c8/wal-000000019 (ops 89-93)
I20260812 06:16:56.415474 14979 log.cc:1079] T ed130596693f481981c6f93d643732c8 P a4b9b25a8d9548f1991eeab6cb232fa8: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/ed130596693f481981c6f93d643732c8/wal-000000020 (ops 94-98)
I20260812 06:16:56.415514 14979 log.cc:1079] T ed130596693f481981c6f93d643732c8 P a4b9b25a8d9548f1991eeab6cb232fa8: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/ed130596693f481981c6f93d643732c8/wal-000000021 (ops 99-103)
I20260812 06:16:56.415556 14979 log.cc:1079] T ed130596693f481981c6f93d643732c8 P a4b9b25a8d9548f1991eeab6cb232fa8: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/ed130596693f481981c6f93d643732c8/wal-000000022 (ops 104-108)
I20260812 06:16:56.415602 14979 log.cc:1079] T ed130596693f481981c6f93d643732c8 P a4b9b25a8d9548f1991eeab6cb232fa8: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/ed130596693f481981c6f93d643732c8/wal-000000023 (ops 109-113)
I20260812 06:16:56.415643 14979 log.cc:1079] T ed130596693f481981c6f93d643732c8 P a4b9b25a8d9548f1991eeab6cb232fa8: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/ed130596693f481981c6f93d643732c8/wal-000000024 (ops 114-118)
I20260812 06:16:56.415683 14979 log.cc:1079] T ed130596693f481981c6f93d643732c8 P a4b9b25a8d9548f1991eeab6cb232fa8: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/ed130596693f481981c6f93d643732c8/wal-000000025 (ops 119-123)
I20260812 06:16:56.415723 14979 log.cc:1079] T ed130596693f481981c6f93d643732c8 P a4b9b25a8d9548f1991eeab6cb232fa8: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/ed130596693f481981c6f93d643732c8/wal-000000026 (ops 124-128)
I20260812 06:16:56.415763 14979 log.cc:1079] T ed130596693f481981c6f93d643732c8 P a4b9b25a8d9548f1991eeab6cb232fa8: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/ed130596693f481981c6f93d643732c8/wal-000000027 (ops 129-133)
I20260812 06:16:56.439765 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: LogGCOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.025s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:16:56.440328 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling UndoDeltaBlockGCOp(ed130596693f481981c6f93d643732c8): 471 bytes on disk
I20260812 06:16:56.440786 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: UndoDeltaBlockGCOp(ed130596693f481981c6f93d643732c8) 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:16:56.441356 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8): perf score=3.181125
I20260812 06:16:56.456184 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.015s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4430855,"delete_count":0,"lbm_write_time_us":4680,"lbm_writes_lt_1ms":111,"reinsert_count":0,"update_count":540}
I20260812 06:16:56.456630 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8): perf score=2.188937
I20260812 06:16:56.467115 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.010s	user 0.003s	sys 0.006s Metrics: {"bytes_written":3774458,"delete_count":0,"lbm_write_time_us":3944,"lbm_writes_lt_1ms":95,"reinsert_count":0,"update_count":460}
I20260812 06:16:56.467584 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling MajorDeltaCompactionOp(ed130596693f481981c6f93d643732c8): perf score=1.000000
I20260812 06:16:56.646572 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: MajorDeltaCompactionOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.179s	user 0.144s	sys 0.034s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877334,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":507,"lbm_read_time_us":12087,"lbm_reads_lt_1ms":674,"lbm_write_time_us":38078,"lbm_writes_lt_1ms":643,"mutex_wait_us":68,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":11520,"thread_start_us":124,"threads_started":1,"update_count":3000}
I20260812 06:16:56.647318 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8): perf score=14.095187
I20260812 06:16:56.694986 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.047s	user 0.016s	sys 0.028s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20192,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:56.695477 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8): perf score=2.188937
I20260812 06:16:56.706836 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4253,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:56.707294 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling MajorDeltaCompactionOp(ed130596693f481981c6f93d643732c8): perf score=1.000000
I20260812 06:16:56.871371 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: MajorDeltaCompactionOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.164s	user 0.109s	sys 0.043s 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":859,"lbm_read_time_us":10436,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30091,"lbm_writes_lt_1ms":543,"mutex_wait_us":266,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":37760,"update_count":2500}
I20260812 06:16:56.871884 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8): perf score=14.095187
I20260812 06:16:56.929443 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.057s	user 0.027s	sys 0.025s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24225,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:56.929955 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling MajorDeltaCompactionOp(ed130596693f481981c6f93d643732c8): perf score=1.000000
I20260812 06:16:57.080243 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: MajorDeltaCompactionOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.150s	user 0.086s	sys 0.056s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672158,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":225,"lbm_read_time_us":9848,"lbm_reads_lt_1ms":463,"lbm_write_time_us":24680,"lbm_writes_lt_1ms":443,"mutex_wait_us":62,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:16:57.080940 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8): perf score=14.095187
I20260812 06:16:57.130174 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.049s	user 0.024s	sys 0.015s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":19070,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:57.130724 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8): perf score=2.188937
I20260812 06:16:57.143097 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.012s	user 0.005s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4474,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:57.143606 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling MajorDeltaCompactionOp(ed130596693f481981c6f93d643732c8): perf score=1.000000
I20260812 06:16:57.318338 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: MajorDeltaCompactionOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.175s	user 0.095s	sys 0.075s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1096,"lbm_read_time_us":10950,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28167,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7808,"update_count":2500}
I20260812 06:16:57.319049 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8): perf score=11.118625
I20260812 06:16:57.354974 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.036s	user 0.022s	sys 0.013s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15205,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:57.355561 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8): perf score=2.188937
I20260812 06:16:57.371047 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.015s	user 0.014s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5902,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:57.371513 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling MajorDeltaCompactionOp(ed130596693f481981c6f93d643732c8): perf score=1.000000
I20260812 06:16:57.501432 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: MajorDeltaCompactionOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.130s	user 0.105s	sys 0.024s 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":1697,"lbm_read_time_us":9001,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25751,"lbm_writes_lt_1ms":443,"mutex_wait_us":295,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":15744,"update_count":2000}
I20260812 06:16:57.502373 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8): perf score=10.126437
I20260812 06:16:57.537802 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.034s	user 0.005s	sys 0.026s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14932,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":1500}
I20260812 06:16:57.538362 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8): perf score=2.188937
I20260812 06:16:57.554121 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.016s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6108,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:57.554718 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling MajorDeltaCompactionOp(ed130596693f481981c6f93d643732c8): perf score=1.000000
I20260812 06:16:57.674098 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: MajorDeltaCompactionOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.119s	user 0.090s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":355,"lbm_read_time_us":10220,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22360,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":63,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8960,"update_count":2000}
I20260812 06:16:57.674744 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8): perf score=10.126437
I20260812 06:16:57.721896 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.047s	user 0.017s	sys 0.026s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16919,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:57.722548 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8): perf score=2.188937
I20260812 06:16:57.733055 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3996,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:57.733530 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling FlushMRSOp(ed130596693f481981c6f93d643732c8): perf score=1.000000
I20260812 06:16:57.773062 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: FlushMRSOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.039s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1152512,"cfile_init":1,"dirs.queue_time_us":60,"dirs.run_cpu_time_us":181,"dirs.run_wall_time_us":1362,"drs_written":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1790,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:16:57.773816 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling LogGCOp(ed130596693f481981c6f93d643732c8): free 111786504 bytes of WAL
I20260812 06:16:57.774032 14979 log_reader.cc:385] T ed130596693f481981c6f93d643732c8: removed 11 log segments from log reader
I20260812 06:16:57.774076 14979 log.cc:1079] T ed130596693f481981c6f93d643732c8 P a4b9b25a8d9548f1991eeab6cb232fa8: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/ed130596693f481981c6f93d643732c8/wal-000000028 (ops 134-138)
I20260812 06:16:57.774102 14979 log.cc:1079] T ed130596693f481981c6f93d643732c8 P a4b9b25a8d9548f1991eeab6cb232fa8: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/ed130596693f481981c6f93d643732c8/wal-000000029 (ops 139-143)
I20260812 06:16:57.774168 14979 log.cc:1079] T ed130596693f481981c6f93d643732c8 P a4b9b25a8d9548f1991eeab6cb232fa8: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/ed130596693f481981c6f93d643732c8/wal-000000030 (ops 144-148)
I20260812 06:16:57.774233 14979 log.cc:1079] T ed130596693f481981c6f93d643732c8 P a4b9b25a8d9548f1991eeab6cb232fa8: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/ed130596693f481981c6f93d643732c8/wal-000000031 (ops 149-152)
I20260812 06:16:57.774299 14979 log.cc:1079] T ed130596693f481981c6f93d643732c8 P a4b9b25a8d9548f1991eeab6cb232fa8: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/ed130596693f481981c6f93d643732c8/wal-000000032 (ops 153-157)
I20260812 06:16:57.774343 14979 log.cc:1079] T ed130596693f481981c6f93d643732c8 P a4b9b25a8d9548f1991eeab6cb232fa8: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/ed130596693f481981c6f93d643732c8/wal-000000033 (ops 158-162)
I20260812 06:16:57.774384 14979 log.cc:1079] T ed130596693f481981c6f93d643732c8 P a4b9b25a8d9548f1991eeab6cb232fa8: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/ed130596693f481981c6f93d643732c8/wal-000000034 (ops 163-167)
I20260812 06:16:57.774425 14979 log.cc:1079] T ed130596693f481981c6f93d643732c8 P a4b9b25a8d9548f1991eeab6cb232fa8: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/ed130596693f481981c6f93d643732c8/wal-000000035 (ops 168-172)
I20260812 06:16:57.774467 14979 log.cc:1079] T ed130596693f481981c6f93d643732c8 P a4b9b25a8d9548f1991eeab6cb232fa8: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/ed130596693f481981c6f93d643732c8/wal-000000036 (ops 173-177)
I20260812 06:16:57.774508 14979 log.cc:1079] T ed130596693f481981c6f93d643732c8 P a4b9b25a8d9548f1991eeab6cb232fa8: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/ed130596693f481981c6f93d643732c8/wal-000000037 (ops 178-182)
I20260812 06:16:57.774549 14979 log.cc:1079] T ed130596693f481981c6f93d643732c8 P a4b9b25a8d9548f1991eeab6cb232fa8: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/ed130596693f481981c6f93d643732c8/wal-000000038 (ops 183-186)
I20260812 06:16:57.796732 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: LogGCOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.023s	user 0.005s	sys 0.015s Metrics: {}
I20260812 06:16:57.797186 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8): perf score=2.188937
I20260812 06:16:57.819232 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.022s	user 0.011s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6383,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:57.819710 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling UndoDeltaBlockGCOp(ed130596693f481981c6f93d643732c8): 447 bytes on disk
I20260812 06:16:57.820116 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: UndoDeltaBlockGCOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4}
I20260812 06:16:57.820639 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8): perf score=2.188937
I20260812 06:16:57.831213 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.010s	user 0.000s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3990,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:57.832048 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling MajorDeltaCompactionOp(ed130596693f481981c6f93d643732c8): perf score=1.000000
I20260812 06:16:58.028270 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: MajorDeltaCompactionOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.196s	user 0.124s	sys 0.070s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877339,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":4591,"lbm_read_time_us":11653,"lbm_reads_lt_1ms":674,"lbm_write_time_us":33802,"lbm_writes_lt_1ms":643,"mutex_wait_us":1980,"peak_mem_usage":75542472,"reinsert_count":0,"thread_start_us":93,"threads_started":1,"update_count":3000}
I20260812 06:16:58.029069 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8): perf score=14.095187
I20260812 06:16:58.076366 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: FlushDeltaMemStoresOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.047s	user 0.027s	sys 0.015s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":19880,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:58.076907 15096 maintenance_manager.cc:419] P a4b9b25a8d9548f1991eeab6cb232fa8: Scheduling MajorDeltaCompactionOp(ed130596693f481981c6f93d643732c8): perf score=1.000000
I20260812 06:16:58.091262 14797 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.917s	user 1.783s	sys 0.162s
I20260812 06:16:58.154040 14797 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.062s	user 0.001s	sys 0.000s
I20260812 06:16:58.154731 14797 tablet_server.cc:179] TabletServer@127.14.115.65:0 shutting down...
I20260812 06:16:58.201263 14979 maintenance_manager.cc:643] P a4b9b25a8d9548f1991eeab6cb232fa8: MajorDeltaCompactionOp(ed130596693f481981c6f93d643732c8) complete. Timing: real 0.124s	user 0.092s	sys 0.032s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672156,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":428,"lbm_read_time_us":10419,"lbm_reads_lt_1ms":459,"lbm_write_time_us":20643,"lbm_writes_lt_1ms":443,"mutex_wait_us":98,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:16:58.202029 14797 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:16:58.202522 14797 tablet_replica.cc:333] T ed130596693f481981c6f93d643732c8 P a4b9b25a8d9548f1991eeab6cb232fa8: stopping tablet replica
I20260812 06:16:58.202768 14797 raft_consensus.cc:2243] T ed130596693f481981c6f93d643732c8 P a4b9b25a8d9548f1991eeab6cb232fa8 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:58.203012 14797 raft_consensus.cc:2272] T ed130596693f481981c6f93d643732c8 P a4b9b25a8d9548f1991eeab6cb232fa8 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:58.219017 14797 tablet_server.cc:196] TabletServer@127.14.115.65:0 shutdown complete.
I20260812 06:16:58.240959 14797 master.cc:562] Master@127.14.115.126:39555 shutting down...
I20260812 06:16:58.244889 14797 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 7dac6e995a4d48c0aa8a0866eb285441 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:58.245100 14797 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 7dac6e995a4d48c0aa8a0866eb285441 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:58.245198 14797 tablet_replica.cc:333] T 00000000000000000000000000000000 P 7dac6e995a4d48c0aa8a0866eb285441: stopping tablet replica
I20260812 06:16:58.257733 14797 master.cc:584] Master@127.14.115.126:39555 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5426 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:16:58.347504 14797 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.14.115.126:37217
I20260812 06:16:58.347925 14797 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:58.349972 15146 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:16:58.350052 15148 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:16:58.350118 15152 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:16:58.350206 14797 server_base.cc:1061] running on GCE node
I20260812 06:16:58.350477 14797 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:58.350538 14797 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:16:58.350564 14797 hybrid_clock.cc:648] HybridClock initialized: now 1786515418350563 us; error 0 us; skew 500 ppm
I20260812 06:16:58.351408 14797 webserver.cc:533] Webserver started at http://127.14.115.126:43207/ using document root <none> and password file <none>
I20260812 06:16:58.351595 14797 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:58.351666 14797 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:58.351748 14797 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:58.352154 14797 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412910501-14797-0/minicluster-data/master-0-root/instance:
uuid: "1a0145d37def47469c9821d14fdc5b90"
format_stamp: "Formatted at 2026-08-12 06:16:58 on dist-test-slave-jztv"
I20260812 06:16:58.353721 14797 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:16:58.355031 15163 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:16:58.355307 14797 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:58.355408 14797 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412910501-14797-0/minicluster-data/master-0-root
uuid: "1a0145d37def47469c9821d14fdc5b90"
format_stamp: "Formatted at 2026-08-12 06:16:58 on dist-test-slave-jztv"
I20260812 06:16:58.355500 14797 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412910501-14797-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412910501-14797-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412910501-14797-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:16:58.369091 14797 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:58.369542 14797 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:58.374289 14797 rpc_server.cc:307] RPC server started. Bound to: 127.14.115.126:37217
I20260812 06:16:58.377415 15258 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.14.115.126:37217 every 8 connection(s)
I20260812 06:16:58.377590 15260 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:16:58.392840 15260 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 1a0145d37def47469c9821d14fdc5b90: Bootstrap starting.
I20260812 06:16:58.393805 15260 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 1a0145d37def47469c9821d14fdc5b90: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:58.395035 15260 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 1a0145d37def47469c9821d14fdc5b90: No bootstrap required, opened a new log
I20260812 06:16:58.395480 15260 raft_consensus.cc:359] T 00000000000000000000000000000000 P 1a0145d37def47469c9821d14fdc5b90 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1a0145d37def47469c9821d14fdc5b90" member_type: VOTER }
I20260812 06:16:58.395589 15260 raft_consensus.cc:385] T 00000000000000000000000000000000 P 1a0145d37def47469c9821d14fdc5b90 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:58.395614 15260 raft_consensus.cc:740] T 00000000000000000000000000000000 P 1a0145d37def47469c9821d14fdc5b90 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 1a0145d37def47469c9821d14fdc5b90, State: Initialized, Role: FOLLOWER
I20260812 06:16:58.395778 15260 consensus_queue.cc:260] T 00000000000000000000000000000000 P 1a0145d37def47469c9821d14fdc5b90 [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: "1a0145d37def47469c9821d14fdc5b90" member_type: VOTER }
I20260812 06:16:58.395876 15260 raft_consensus.cc:399] T 00000000000000000000000000000000 P 1a0145d37def47469c9821d14fdc5b90 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:58.395903 15260 raft_consensus.cc:493] T 00000000000000000000000000000000 P 1a0145d37def47469c9821d14fdc5b90 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:58.395934 15260 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 1a0145d37def47469c9821d14fdc5b90 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:58.396661 15260 raft_consensus.cc:515] T 00000000000000000000000000000000 P 1a0145d37def47469c9821d14fdc5b90 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1a0145d37def47469c9821d14fdc5b90" member_type: VOTER }
I20260812 06:16:58.396780 15260 leader_election.cc:304] T 00000000000000000000000000000000 P 1a0145d37def47469c9821d14fdc5b90 [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: 1a0145d37def47469c9821d14fdc5b90; no voters: 
I20260812 06:16:58.396958 15260 leader_election.cc:290] T 00000000000000000000000000000000 P 1a0145d37def47469c9821d14fdc5b90 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:58.397130 15263 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 1a0145d37def47469c9821d14fdc5b90 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:58.397370 15263 raft_consensus.cc:697] T 00000000000000000000000000000000 P 1a0145d37def47469c9821d14fdc5b90 [term 1 LEADER]: Becoming Leader. State: Replica: 1a0145d37def47469c9821d14fdc5b90, State: Running, Role: LEADER
I20260812 06:16:58.397513 15260 sys_catalog.cc:565] T 00000000000000000000000000000000 P 1a0145d37def47469c9821d14fdc5b90 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:58.397545 15263 consensus_queue.cc:237] T 00000000000000000000000000000000 P 1a0145d37def47469c9821d14fdc5b90 [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: "1a0145d37def47469c9821d14fdc5b90" member_type: VOTER }
I20260812 06:16:58.398005 15267 sys_catalog.cc:455] T 00000000000000000000000000000000 P 1a0145d37def47469c9821d14fdc5b90 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 1a0145d37def47469c9821d14fdc5b90. Latest consensus state: current_term: 1 leader_uuid: "1a0145d37def47469c9821d14fdc5b90" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1a0145d37def47469c9821d14fdc5b90" member_type: VOTER } }
I20260812 06:16:58.397989 15264 sys_catalog.cc:455] T 00000000000000000000000000000000 P 1a0145d37def47469c9821d14fdc5b90 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "1a0145d37def47469c9821d14fdc5b90" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1a0145d37def47469c9821d14fdc5b90" member_type: VOTER } }
I20260812 06:16:58.398108 15267 sys_catalog.cc:458] T 00000000000000000000000000000000 P 1a0145d37def47469c9821d14fdc5b90 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:58.398118 15264 sys_catalog.cc:458] T 00000000000000000000000000000000 P 1a0145d37def47469c9821d14fdc5b90 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:58.398957 15271 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:58.400033 15271 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:58.400254 14797 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:58.401896 15271 catalog_manager.cc:1383] Generated new cluster ID: 82ecbe464a3d4570a3a1ac10cc2a5576
I20260812 06:16:58.401966 15271 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:58.407817 15271 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:58.408381 15271 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:58.414852 15271 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 1a0145d37def47469c9821d14fdc5b90: Generated new TSK 0
I20260812 06:16:58.415045 15271 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:58.416464 14797 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:58.418457 15297 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:16:58.418553 14797 server_base.cc:1061] running on GCE node
W20260812 06:16:58.418581 15299 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:16:58.418762 15296 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:16:58.418957 14797 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:58.419019 14797 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:16:58.419054 14797 hybrid_clock.cc:648] HybridClock initialized: now 1786515418419052 us; error 0 us; skew 500 ppm
I20260812 06:16:58.420046 14797 webserver.cc:533] Webserver started at http://127.14.115.65:46451/ using document root <none> and password file <none>
I20260812 06:16:58.420250 14797 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:58.420348 14797 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:58.420432 14797 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:58.420833 14797 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412910501-14797-0/minicluster-data/ts-0-root/instance:
uuid: "8e712cc0207b4a7589bce39a6c8db3e6"
format_stamp: "Formatted at 2026-08-12 06:16:58 on dist-test-slave-jztv"
I20260812 06:16:58.422438 14797 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:16:58.423447 15306 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:16:58.423703 14797 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:58.423792 14797 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412910501-14797-0/minicluster-data/ts-0-root
uuid: "8e712cc0207b4a7589bce39a6c8db3e6"
format_stamp: "Formatted at 2026-08-12 06:16:58 on dist-test-slave-jztv"
I20260812 06:16:58.423892 14797 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412910501-14797-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412910501-14797-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412910501-14797-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:16:58.442282 14797 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:58.442698 14797 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:58.443044 14797 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:58.443535 14797 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:58.443596 14797 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:58.443657 14797 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:58.443708 14797 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:58.448175 14797 rpc_server.cc:307] RPC server started. Bound to: 127.14.115.65:36161
I20260812 06:16:58.448215 15402 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.14.115.65:36161 every 8 connection(s)
I20260812 06:16:58.456993 15404 heartbeater.cc:344] Connected to a master server at 127.14.115.126:37217
I20260812 06:16:58.457121 15404 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:58.457327 15404 heartbeater.cc:507] Master 127.14.115.126:37217 requested a full tablet report, sending...
I20260812 06:16:58.457999 15193 ts_manager.cc:194] Registered new tserver with Master: 8e712cc0207b4a7589bce39a6c8db3e6 (127.14.115.65:36161)
I20260812 06:16:58.458654 14797 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.010055595s
I20260812 06:16:58.458864 15193 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:49962
I20260812 06:16:58.466100 15193 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:49976:
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:16:58.475426 15350 tablet_service.cc:1511] Processing CreateTablet for tablet 745a3f4b44214931a951605644fa3076 (DEFAULT_TABLE table=heavy-update-compaction-test [id=7003fac0d4eb45cfa1eddb8b5e674524]), partition=
I20260812 06:16:58.475692 15350 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 745a3f4b44214931a951605644fa3076. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:58.477864 15423 tablet_bootstrap.cc:492] T 745a3f4b44214931a951605644fa3076 P 8e712cc0207b4a7589bce39a6c8db3e6: Bootstrap starting.
I20260812 06:16:58.478835 15423 tablet_bootstrap.cc:654] T 745a3f4b44214931a951605644fa3076 P 8e712cc0207b4a7589bce39a6c8db3e6: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:58.479981 15423 tablet_bootstrap.cc:492] T 745a3f4b44214931a951605644fa3076 P 8e712cc0207b4a7589bce39a6c8db3e6: No bootstrap required, opened a new log
I20260812 06:16:58.480101 15423 ts_tablet_manager.cc:1403] T 745a3f4b44214931a951605644fa3076 P 8e712cc0207b4a7589bce39a6c8db3e6: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:16:58.480564 15423 raft_consensus.cc:359] T 745a3f4b44214931a951605644fa3076 P 8e712cc0207b4a7589bce39a6c8db3e6 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8e712cc0207b4a7589bce39a6c8db3e6" member_type: VOTER last_known_addr { host: "127.14.115.65" port: 36161 } }
I20260812 06:16:58.480685 15423 raft_consensus.cc:385] T 745a3f4b44214931a951605644fa3076 P 8e712cc0207b4a7589bce39a6c8db3e6 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:58.480733 15423 raft_consensus.cc:740] T 745a3f4b44214931a951605644fa3076 P 8e712cc0207b4a7589bce39a6c8db3e6 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 8e712cc0207b4a7589bce39a6c8db3e6, State: Initialized, Role: FOLLOWER
I20260812 06:16:58.480901 15423 consensus_queue.cc:260] T 745a3f4b44214931a951605644fa3076 P 8e712cc0207b4a7589bce39a6c8db3e6 [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: "8e712cc0207b4a7589bce39a6c8db3e6" member_type: VOTER last_known_addr { host: "127.14.115.65" port: 36161 } }
I20260812 06:16:58.481029 15423 raft_consensus.cc:399] T 745a3f4b44214931a951605644fa3076 P 8e712cc0207b4a7589bce39a6c8db3e6 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:58.481084 15423 raft_consensus.cc:493] T 745a3f4b44214931a951605644fa3076 P 8e712cc0207b4a7589bce39a6c8db3e6 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:58.481146 15423 raft_consensus.cc:3060] T 745a3f4b44214931a951605644fa3076 P 8e712cc0207b4a7589bce39a6c8db3e6 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:58.481920 15423 raft_consensus.cc:515] T 745a3f4b44214931a951605644fa3076 P 8e712cc0207b4a7589bce39a6c8db3e6 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8e712cc0207b4a7589bce39a6c8db3e6" member_type: VOTER last_known_addr { host: "127.14.115.65" port: 36161 } }
I20260812 06:16:58.482084 15423 leader_election.cc:304] T 745a3f4b44214931a951605644fa3076 P 8e712cc0207b4a7589bce39a6c8db3e6 [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: 8e712cc0207b4a7589bce39a6c8db3e6; no voters: 
I20260812 06:16:58.482316 15423 leader_election.cc:290] T 745a3f4b44214931a951605644fa3076 P 8e712cc0207b4a7589bce39a6c8db3e6 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:58.482478 15425 raft_consensus.cc:2804] T 745a3f4b44214931a951605644fa3076 P 8e712cc0207b4a7589bce39a6c8db3e6 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:58.482728 15404 heartbeater.cc:499] Master 127.14.115.126:37217 was elected leader, sending a full tablet report...
I20260812 06:16:58.482738 15425 raft_consensus.cc:697] T 745a3f4b44214931a951605644fa3076 P 8e712cc0207b4a7589bce39a6c8db3e6 [term 1 LEADER]: Becoming Leader. State: Replica: 8e712cc0207b4a7589bce39a6c8db3e6, State: Running, Role: LEADER
I20260812 06:16:58.482743 15423 ts_tablet_manager.cc:1434] T 745a3f4b44214931a951605644fa3076 P 8e712cc0207b4a7589bce39a6c8db3e6: Time spent starting tablet: real 0.003s	user 0.001s	sys 0.002s
I20260812 06:16:58.482911 15425 consensus_queue.cc:237] T 745a3f4b44214931a951605644fa3076 P 8e712cc0207b4a7589bce39a6c8db3e6 [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: "8e712cc0207b4a7589bce39a6c8db3e6" member_type: VOTER last_known_addr { host: "127.14.115.65" port: 36161 } }
I20260812 06:16:58.484223 15193 catalog_manager.cc:5719] T 745a3f4b44214931a951605644fa3076 P 8e712cc0207b4a7589bce39a6c8db3e6 reported cstate change: term changed from 0 to 1, leader changed from <none> to 8e712cc0207b4a7589bce39a6c8db3e6 (127.14.115.65). New cstate: current_term: 1 leader_uuid: "8e712cc0207b4a7589bce39a6c8db3e6" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8e712cc0207b4a7589bce39a6c8db3e6" member_type: VOTER last_known_addr { host: "127.14.115.65" port: 36161 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:58.543479 14797 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.052s	user 0.015s	sys 0.008s
I20260812 06:16:58.699162 15405 maintenance_manager.cc:419] P 8e712cc0207b4a7589bce39a6c8db3e6: Scheduling FlushMRSOp(745a3f4b44214931a951605644fa3076): perf score=19.054940
I20260812 06:16:58.863700 15314 maintenance_manager.cc:643] P 8e712cc0207b4a7589bce39a6c8db3e6: FlushMRSOp(745a3f4b44214931a951605644fa3076) complete. Timing: real 0.164s	user 0.127s	sys 0.036s Metrics: {"bytes_written":13866409,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":72,"dirs.run_cpu_time_us":243,"dirs.run_wall_time_us":1018,"drs_written":1,"lbm_read_time_us":45,"lbm_reads_lt_1ms":4,"lbm_write_time_us":41215,"lbm_writes_lt_1ms":795,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":17408,"update_count":1690}
I20260812 06:16:58.864563 15405 maintenance_manager.cc:419] P 8e712cc0207b4a7589bce39a6c8db3e6: Scheduling LogGCOp(745a3f4b44214931a951605644fa3076): free 20743880 bytes of WAL
I20260812 06:16:58.864883 15314 log_reader.cc:385] T 745a3f4b44214931a951605644fa3076: removed 2 log segments from log reader
I20260812 06:16:58.864960 15314 log.cc:1079] T 745a3f4b44214931a951605644fa3076 P 8e712cc0207b4a7589bce39a6c8db3e6: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/745a3f4b44214931a951605644fa3076/wal-000000001 (ops 1-6)
I20260812 06:16:58.865023 15314 log.cc:1079] T 745a3f4b44214931a951605644fa3076 P 8e712cc0207b4a7589bce39a6c8db3e6: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/745a3f4b44214931a951605644fa3076/wal-000000002 (ops 7-11)
I20260812 06:16:58.870715 15314 maintenance_manager.cc:643] P 8e712cc0207b4a7589bce39a6c8db3e6: LogGCOp(745a3f4b44214931a951605644fa3076) complete. Timing: real 0.006s	user 0.000s	sys 0.006s Metrics: {}
I20260812 06:16:58.871047 15405 maintenance_manager.cc:419] P 8e712cc0207b4a7589bce39a6c8db3e6: Scheduling FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076): perf score=1.196750
I20260812 06:16:58.888995 15314 maintenance_manager.cc:643] P 8e712cc0207b4a7589bce39a6c8db3e6: FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076) complete. Timing: real 0.018s	user 0.004s	sys 0.009s Metrics: {"bytes_written":2953959,"delete_count":0,"lbm_write_time_us":2652,"lbm_writes_lt_1ms":75,"reinsert_count":0,"update_count":360}
I20260812 06:16:58.889505 15405 maintenance_manager.cc:419] P 8e712cc0207b4a7589bce39a6c8db3e6: Scheduling UndoDeltaBlockGCOp(745a3f4b44214931a951605644fa3076): 16411404 bytes on disk
I20260812 06:16:58.889972 15314 maintenance_manager.cc:643] P 8e712cc0207b4a7589bce39a6c8db3e6: UndoDeltaBlockGCOp(745a3f4b44214931a951605644fa3076) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4}
I20260812 06:16:58.890419 15405 maintenance_manager.cc:419] P 8e712cc0207b4a7589bce39a6c8db3e6: Scheduling FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076): perf score=2.188937
I20260812 06:16:58.900560 15314 maintenance_manager.cc:643] P 8e712cc0207b4a7589bce39a6c8db3e6: FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3958,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:58.900933 15405 maintenance_manager.cc:419] P 8e712cc0207b4a7589bce39a6c8db3e6: Scheduling MajorDeltaCompactionOp(745a3f4b44214931a951605644fa3076): perf score=1.000000
I20260812 06:16:59.092751 15314 maintenance_manager.cc:643] P 8e712cc0207b4a7589bce39a6c8db3e6: MajorDeltaCompactionOp(745a3f4b44214931a951605644fa3076) complete. Timing: real 0.192s	user 0.103s	sys 0.081s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774773,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1452,"lbm_read_time_us":13171,"lbm_reads_lt_1ms":569,"lbm_write_time_us":30208,"lbm_writes_lt_1ms":543,"mutex_wait_us":307,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9600,"thread_start_us":349,"threads_started":5,"update_count":2500}
I20260812 06:16:59.093354 15405 maintenance_manager.cc:419] P 8e712cc0207b4a7589bce39a6c8db3e6: Scheduling FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076): perf score=14.095187
I20260812 06:16:59.141484 15314 maintenance_manager.cc:643] P 8e712cc0207b4a7589bce39a6c8db3e6: FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076) complete. Timing: real 0.048s	user 0.029s	sys 0.016s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21150,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:59.141975 15405 maintenance_manager.cc:419] P 8e712cc0207b4a7589bce39a6c8db3e6: Scheduling FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076): perf score=2.188937
I20260812 06:16:59.166587 15314 maintenance_manager.cc:643] P 8e712cc0207b4a7589bce39a6c8db3e6: FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076) complete. Timing: real 0.024s	user 0.009s	sys 0.015s 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:16:59.167085 15405 maintenance_manager.cc:419] P 8e712cc0207b4a7589bce39a6c8db3e6: Scheduling MajorDeltaCompactionOp(745a3f4b44214931a951605644fa3076): perf score=1.000000
I20260812 06:16:59.346148 15314 maintenance_manager.cc:643] P 8e712cc0207b4a7589bce39a6c8db3e6: MajorDeltaCompactionOp(745a3f4b44214931a951605644fa3076) complete. Timing: real 0.179s	user 0.126s	sys 0.053s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":230,"lbm_read_time_us":11117,"lbm_reads_lt_1ms":564,"lbm_write_time_us":27365,"lbm_writes_lt_1ms":543,"mutex_wait_us":20,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10368,"update_count":2500}
I20260812 06:16:59.346899 15405 maintenance_manager.cc:419] P 8e712cc0207b4a7589bce39a6c8db3e6: Scheduling FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076): perf score=14.095187
I20260812 06:16:59.394542 15314 maintenance_manager.cc:643] P 8e712cc0207b4a7589bce39a6c8db3e6: FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076) complete. Timing: real 0.047s	user 0.032s	sys 0.015s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20926,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:59.395088 15405 maintenance_manager.cc:419] P 8e712cc0207b4a7589bce39a6c8db3e6: Scheduling FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076): perf score=2.188937
I20260812 06:16:59.412148 15314 maintenance_manager.cc:643] P 8e712cc0207b4a7589bce39a6c8db3e6: FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076) complete. Timing: real 0.017s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6565,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:59.412585 15405 maintenance_manager.cc:419] P 8e712cc0207b4a7589bce39a6c8db3e6: Scheduling MajorDeltaCompactionOp(745a3f4b44214931a951605644fa3076): perf score=1.000000
I20260812 06:16:59.570806 15314 maintenance_manager.cc:643] P 8e712cc0207b4a7589bce39a6c8db3e6: MajorDeltaCompactionOp(745a3f4b44214931a951605644fa3076) complete. Timing: real 0.158s	user 0.123s	sys 0.032s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":84,"lbm_read_time_us":11241,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26794,"lbm_writes_lt_1ms":543,"mutex_wait_us":55,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13312,"update_count":2500}
I20260812 06:16:59.571450 15405 maintenance_manager.cc:419] P 8e712cc0207b4a7589bce39a6c8db3e6: Scheduling FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076): perf score=11.118625
I20260812 06:16:59.608134 15314 maintenance_manager.cc:643] P 8e712cc0207b4a7589bce39a6c8db3e6: FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076) complete. Timing: real 0.036s	user 0.027s	sys 0.008s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":15207,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:59.608799 15405 maintenance_manager.cc:419] P 8e712cc0207b4a7589bce39a6c8db3e6: Scheduling FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076): perf score=2.188937
I20260812 06:16:59.625371 15314 maintenance_manager.cc:643] P 8e712cc0207b4a7589bce39a6c8db3e6: FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076) complete. Timing: real 0.016s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5540,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:59.625802 15405 maintenance_manager.cc:419] P 8e712cc0207b4a7589bce39a6c8db3e6: Scheduling MajorDeltaCompactionOp(745a3f4b44214931a951605644fa3076): perf score=1.000000
I20260812 06:16:59.752672 15314 maintenance_manager.cc:643] P 8e712cc0207b4a7589bce39a6c8db3e6: MajorDeltaCompactionOp(745a3f4b44214931a951605644fa3076) complete. Timing: real 0.127s	user 0.102s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672267,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":348,"lbm_read_time_us":7396,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24202,"lbm_writes_lt_1ms":443,"mutex_wait_us":44,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8320,"update_count":2000}
I20260812 06:16:59.753444 15405 maintenance_manager.cc:419] P 8e712cc0207b4a7589bce39a6c8db3e6: Scheduling FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076): perf score=11.118625
I20260812 06:16:59.782735 15314 maintenance_manager.cc:643] P 8e712cc0207b4a7589bce39a6c8db3e6: FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076) complete. Timing: real 0.029s	user 0.009s	sys 0.019s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":13019,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:59.783192 15405 maintenance_manager.cc:419] P 8e712cc0207b4a7589bce39a6c8db3e6: Scheduling FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076): perf score=2.188937
I20260812 06:16:59.792472 15314 maintenance_manager.cc:643] P 8e712cc0207b4a7589bce39a6c8db3e6: FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3460,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:59.792876 15405 maintenance_manager.cc:419] P 8e712cc0207b4a7589bce39a6c8db3e6: Scheduling MajorDeltaCompactionOp(745a3f4b44214931a951605644fa3076): perf score=1.000000
I20260812 06:16:59.917161 15314 maintenance_manager.cc:643] P 8e712cc0207b4a7589bce39a6c8db3e6: MajorDeltaCompactionOp(745a3f4b44214931a951605644fa3076) complete. Timing: real 0.124s	user 0.104s	sys 0.020s 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":1276,"lbm_read_time_us":9736,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22289,"lbm_writes_lt_1ms":443,"mutex_wait_us":302,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9472,"update_count":2000}
I20260812 06:16:59.917725 15405 maintenance_manager.cc:419] P 8e712cc0207b4a7589bce39a6c8db3e6: Scheduling FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076): perf score=10.126437
I20260812 06:16:59.976747 15314 maintenance_manager.cc:643] P 8e712cc0207b4a7589bce39a6c8db3e6: FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076) complete. Timing: real 0.059s	user 0.019s	sys 0.023s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16681,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:59.977262 15405 maintenance_manager.cc:419] P 8e712cc0207b4a7589bce39a6c8db3e6: Scheduling FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076): perf score=2.188937
I20260812 06:16:59.987532 15314 maintenance_manager.cc:643] P 8e712cc0207b4a7589bce39a6c8db3e6: FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4026,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:59.988181 15405 maintenance_manager.cc:419] P 8e712cc0207b4a7589bce39a6c8db3e6: Scheduling MajorDeltaCompactionOp(745a3f4b44214931a951605644fa3076): perf score=1.000000
I20260812 06:17:00.147014 15314 maintenance_manager.cc:643] P 8e712cc0207b4a7589bce39a6c8db3e6: MajorDeltaCompactionOp(745a3f4b44214931a951605644fa3076) complete. Timing: real 0.159s	user 0.110s	sys 0.048s 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":1416,"lbm_read_time_us":10944,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26072,"lbm_writes_lt_1ms":443,"mutex_wait_us":310,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":18304,"update_count":2000}
I20260812 06:17:00.147967 15405 maintenance_manager.cc:419] P 8e712cc0207b4a7589bce39a6c8db3e6: Scheduling FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076): perf score=10.126437
I20260812 06:17:00.187474 15314 maintenance_manager.cc:643] P 8e712cc0207b4a7589bce39a6c8db3e6: FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076) complete. Timing: real 0.039s	user 0.025s	sys 0.012s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":17009,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:00.187953 15405 maintenance_manager.cc:419] P 8e712cc0207b4a7589bce39a6c8db3e6: Scheduling FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076): perf score=2.188937
I20260812 06:17:00.198398 15314 maintenance_manager.cc:643] P 8e712cc0207b4a7589bce39a6c8db3e6: FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076) complete. Timing: real 0.010s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4063,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:00.199534 15405 maintenance_manager.cc:419] P 8e712cc0207b4a7589bce39a6c8db3e6: Scheduling FlushMRSOp(745a3f4b44214931a951605644fa3076): perf score=1.000000
I20260812 06:17:00.228071 15314 maintenance_manager.cc:643] P 8e712cc0207b4a7589bce39a6c8db3e6: FlushMRSOp(745a3f4b44214931a951605644fa3076) complete. Timing: real 0.028s	user 0.027s	sys 0.000s Metrics: {"bytes_written":1275443,"cfile_init":1,"dirs.queue_time_us":56,"dirs.run_cpu_time_us":256,"dirs.run_wall_time_us":1520,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1594,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:00.228664 15405 maintenance_manager.cc:419] P 8e712cc0207b4a7589bce39a6c8db3e6: Scheduling LogGCOp(745a3f4b44214931a951605644fa3076): free 124257246 bytes of WAL
I20260812 06:17:00.228909 15314 log_reader.cc:385] T 745a3f4b44214931a951605644fa3076: removed 12 log segments from log reader
I20260812 06:17:00.228956 15314 log.cc:1079] T 745a3f4b44214931a951605644fa3076 P 8e712cc0207b4a7589bce39a6c8db3e6: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/745a3f4b44214931a951605644fa3076/wal-000000003 (ops 12-16)
I20260812 06:17:00.228986 15314 log.cc:1079] T 745a3f4b44214931a951605644fa3076 P 8e712cc0207b4a7589bce39a6c8db3e6: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/745a3f4b44214931a951605644fa3076/wal-000000004 (ops 17-20)
I20260812 06:17:00.229048 15314 log.cc:1079] T 745a3f4b44214931a951605644fa3076 P 8e712cc0207b4a7589bce39a6c8db3e6: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/745a3f4b44214931a951605644fa3076/wal-000000005 (ops 21-25)
I20260812 06:17:00.229094 15314 log.cc:1079] T 745a3f4b44214931a951605644fa3076 P 8e712cc0207b4a7589bce39a6c8db3e6: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/745a3f4b44214931a951605644fa3076/wal-000000006 (ops 26-30)
I20260812 06:17:00.229131 15314 log.cc:1079] T 745a3f4b44214931a951605644fa3076 P 8e712cc0207b4a7589bce39a6c8db3e6: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/745a3f4b44214931a951605644fa3076/wal-000000007 (ops 31-35)
I20260812 06:17:00.229190 15314 log.cc:1079] T 745a3f4b44214931a951605644fa3076 P 8e712cc0207b4a7589bce39a6c8db3e6: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/745a3f4b44214931a951605644fa3076/wal-000000008 (ops 36-40)
I20260812 06:17:00.229224 15314 log.cc:1079] T 745a3f4b44214931a951605644fa3076 P 8e712cc0207b4a7589bce39a6c8db3e6: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/745a3f4b44214931a951605644fa3076/wal-000000009 (ops 41-45)
I20260812 06:17:00.229262 15314 log.cc:1079] T 745a3f4b44214931a951605644fa3076 P 8e712cc0207b4a7589bce39a6c8db3e6: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/745a3f4b44214931a951605644fa3076/wal-000000010 (ops 46-50)
I20260812 06:17:00.229303 15314 log.cc:1079] T 745a3f4b44214931a951605644fa3076 P 8e712cc0207b4a7589bce39a6c8db3e6: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/745a3f4b44214931a951605644fa3076/wal-000000011 (ops 51-55)
I20260812 06:17:00.229343 15314 log.cc:1079] T 745a3f4b44214931a951605644fa3076 P 8e712cc0207b4a7589bce39a6c8db3e6: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/745a3f4b44214931a951605644fa3076/wal-000000012 (ops 56-60)
I20260812 06:17:00.229382 15314 log.cc:1079] T 745a3f4b44214931a951605644fa3076 P 8e712cc0207b4a7589bce39a6c8db3e6: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/745a3f4b44214931a951605644fa3076/wal-000000013 (ops 61-65)
I20260812 06:17:00.229420 15314 log.cc:1079] T 745a3f4b44214931a951605644fa3076 P 8e712cc0207b4a7589bce39a6c8db3e6: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/745a3f4b44214931a951605644fa3076/wal-000000014 (ops 66-70)
I20260812 06:17:00.257452 15314 maintenance_manager.cc:643] P 8e712cc0207b4a7589bce39a6c8db3e6: LogGCOp(745a3f4b44214931a951605644fa3076) complete. Timing: real 0.029s	user 0.003s	sys 0.023s Metrics: {}
I20260812 06:17:00.258015 15405 maintenance_manager.cc:419] P 8e712cc0207b4a7589bce39a6c8db3e6: Scheduling UndoDeltaBlockGCOp(745a3f4b44214931a951605644fa3076): 483 bytes on disk
I20260812 06:17:00.258685 15314 maintenance_manager.cc:643] P 8e712cc0207b4a7589bce39a6c8db3e6: UndoDeltaBlockGCOp(745a3f4b44214931a951605644fa3076) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4}
I20260812 06:17:00.259301 15405 maintenance_manager.cc:419] P 8e712cc0207b4a7589bce39a6c8db3e6: Scheduling FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076): perf score=4.173312
I20260812 06:17:00.283869 15314 maintenance_manager.cc:643] P 8e712cc0207b4a7589bce39a6c8db3e6: FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076) complete. Timing: real 0.024s	user 0.008s	sys 0.014s Metrics: {"bytes_written":5866704,"delete_count":0,"lbm_write_time_us":6239,"lbm_writes_lt_1ms":146,"reinsert_count":0,"update_count":715}
I20260812 06:17:00.284597 15405 maintenance_manager.cc:419] P 8e712cc0207b4a7589bce39a6c8db3e6: Scheduling FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076): perf score=1.196750
I20260812 06:17:00.293360 15314 maintenance_manager.cc:643] P 8e712cc0207b4a7589bce39a6c8db3e6: FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076) complete. Timing: real 0.009s	user 0.000s	sys 0.007s Metrics: {"bytes_written":2338579,"delete_count":0,"lbm_write_time_us":3041,"lbm_writes_lt_1ms":60,"reinsert_count":0,"update_count":285}
I20260812 06:17:00.293866 15405 maintenance_manager.cc:419] P 8e712cc0207b4a7589bce39a6c8db3e6: Scheduling MajorDeltaCompactionOp(745a3f4b44214931a951605644fa3076): perf score=1.000000
I20260812 06:17:00.496954 15314 maintenance_manager.cc:643] P 8e712cc0207b4a7589bce39a6c8db3e6: MajorDeltaCompactionOp(745a3f4b44214931a951605644fa3076) complete. Timing: real 0.203s	user 0.129s	sys 0.071s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877300,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":301,"lbm_read_time_us":14599,"lbm_reads_lt_1ms":674,"lbm_write_time_us":32364,"lbm_writes_lt_1ms":643,"mutex_wait_us":23,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":12800,"thread_start_us":109,"threads_started":1,"update_count":3000}
I20260812 06:17:00.497696 15405 maintenance_manager.cc:419] P 8e712cc0207b4a7589bce39a6c8db3e6: Scheduling FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076): perf score=14.095187
I20260812 06:17:00.552325 15314 maintenance_manager.cc:643] P 8e712cc0207b4a7589bce39a6c8db3e6: FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076) complete. Timing: real 0.054s	user 0.014s	sys 0.038s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":19749,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:00.552897 15405 maintenance_manager.cc:419] P 8e712cc0207b4a7589bce39a6c8db3e6: Scheduling FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076): perf score=2.188937
I20260812 06:17:00.568281 15314 maintenance_manager.cc:643] P 8e712cc0207b4a7589bce39a6c8db3e6: FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076) complete. Timing: real 0.015s	user 0.004s	sys 0.010s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5604,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:00.568859 15405 maintenance_manager.cc:419] P 8e712cc0207b4a7589bce39a6c8db3e6: Scheduling MajorDeltaCompactionOp(745a3f4b44214931a951605644fa3076): perf score=1.000000
I20260812 06:17:00.751866 15314 maintenance_manager.cc:643] P 8e712cc0207b4a7589bce39a6c8db3e6: MajorDeltaCompactionOp(745a3f4b44214931a951605644fa3076) complete. Timing: real 0.183s	user 0.125s	sys 0.057s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774684,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":294,"lbm_read_time_us":13072,"lbm_reads_lt_1ms":564,"lbm_write_time_us":27063,"lbm_writes_lt_1ms":543,"mutex_wait_us":34,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2500}
I20260812 06:17:00.752470 15405 maintenance_manager.cc:419] P 8e712cc0207b4a7589bce39a6c8db3e6: Scheduling FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076): perf score=14.095187
I20260812 06:17:00.797858 15314 maintenance_manager.cc:643] P 8e712cc0207b4a7589bce39a6c8db3e6: FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076) complete. Timing: real 0.045s	user 0.023s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20151,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:00.798403 15405 maintenance_manager.cc:419] P 8e712cc0207b4a7589bce39a6c8db3e6: Scheduling FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076): perf score=2.188937
I20260812 06:17:00.811630 15314 maintenance_manager.cc:643] P 8e712cc0207b4a7589bce39a6c8db3e6: FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076) complete. Timing: real 0.013s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4946,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:00.812121 15405 maintenance_manager.cc:419] P 8e712cc0207b4a7589bce39a6c8db3e6: Scheduling MajorDeltaCompactionOp(745a3f4b44214931a951605644fa3076): perf score=1.000000
I20260812 06:17:01.006625 15314 maintenance_manager.cc:643] P 8e712cc0207b4a7589bce39a6c8db3e6: MajorDeltaCompactionOp(745a3f4b44214931a951605644fa3076) complete. Timing: real 0.194s	user 0.115s	sys 0.070s 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":183,"lbm_read_time_us":10899,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30537,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5248,"update_count":2500}
I20260812 06:17:01.007320 15405 maintenance_manager.cc:419] P 8e712cc0207b4a7589bce39a6c8db3e6: Scheduling FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076): perf score=14.095187
I20260812 06:17:01.055405 15314 maintenance_manager.cc:643] P 8e712cc0207b4a7589bce39a6c8db3e6: FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076) complete. Timing: real 0.048s	user 0.021s	sys 0.021s Metrics: {"bytes_written":16409899,"delete_count":0,"lbm_write_time_us":18779,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:01.055874 15405 maintenance_manager.cc:419] P 8e712cc0207b4a7589bce39a6c8db3e6: Scheduling FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076): perf score=2.188937
I20260812 06:17:01.067899 15314 maintenance_manager.cc:643] P 8e712cc0207b4a7589bce39a6c8db3e6: FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076) complete. Timing: real 0.012s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4447,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:01.068398 15405 maintenance_manager.cc:419] P 8e712cc0207b4a7589bce39a6c8db3e6: Scheduling MajorDeltaCompactionOp(745a3f4b44214931a951605644fa3076): perf score=1.000000
I20260812 06:17:01.233924 15314 maintenance_manager.cc:643] P 8e712cc0207b4a7589bce39a6c8db3e6: MajorDeltaCompactionOp(745a3f4b44214931a951605644fa3076) complete. Timing: real 0.165s	user 0.117s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":180,"lbm_read_time_us":11619,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31124,"lbm_writes_lt_1ms":543,"mutex_wait_us":32,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":38528,"update_count":2500}
I20260812 06:17:01.234709 15405 maintenance_manager.cc:419] P 8e712cc0207b4a7589bce39a6c8db3e6: Scheduling FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076): perf score=11.118625
I20260812 06:17:01.271950 15314 maintenance_manager.cc:643] P 8e712cc0207b4a7589bce39a6c8db3e6: FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076) complete. Timing: real 0.037s	user 0.023s	sys 0.012s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":15515,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:01.272470 15405 maintenance_manager.cc:419] P 8e712cc0207b4a7589bce39a6c8db3e6: Scheduling FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076): perf score=2.188937
I20260812 06:17:01.291587 15314 maintenance_manager.cc:643] P 8e712cc0207b4a7589bce39a6c8db3e6: FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076) complete. Timing: real 0.019s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4458,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:01.292071 15405 maintenance_manager.cc:419] P 8e712cc0207b4a7589bce39a6c8db3e6: Scheduling FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076): perf score=2.188937
I20260812 06:17:01.302053 15314 maintenance_manager.cc:643] P 8e712cc0207b4a7589bce39a6c8db3e6: FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3767,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:01.302685 15405 maintenance_manager.cc:419] P 8e712cc0207b4a7589bce39a6c8db3e6: Scheduling MajorDeltaCompactionOp(745a3f4b44214931a951605644fa3076): perf score=1.000000
I20260812 06:17:01.453837 15314 maintenance_manager.cc:643] P 8e712cc0207b4a7589bce39a6c8db3e6: MajorDeltaCompactionOp(745a3f4b44214931a951605644fa3076) complete. Timing: real 0.151s	user 0.110s	sys 0.039s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774801,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":89,"lbm_read_time_us":11186,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29818,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7424,"update_count":2500}
I20260812 06:17:01.454588 15405 maintenance_manager.cc:419] P 8e712cc0207b4a7589bce39a6c8db3e6: Scheduling FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076): perf score=10.126437
I20260812 06:17:01.503098 15314 maintenance_manager.cc:643] P 8e712cc0207b4a7589bce39a6c8db3e6: FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076) complete. Timing: real 0.048s	user 0.031s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19029,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:01.503646 15405 maintenance_manager.cc:419] P 8e712cc0207b4a7589bce39a6c8db3e6: Scheduling FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076): perf score=2.188937
I20260812 06:17:01.527140 15314 maintenance_manager.cc:643] P 8e712cc0207b4a7589bce39a6c8db3e6: FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076) complete. Timing: real 0.023s	user 0.005s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4658,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":500}
I20260812 06:17:01.527635 15405 maintenance_manager.cc:419] P 8e712cc0207b4a7589bce39a6c8db3e6: Scheduling FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076): perf score=2.188937
I20260812 06:17:01.542461 15314 maintenance_manager.cc:643] P 8e712cc0207b4a7589bce39a6c8db3e6: FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076) complete. Timing: real 0.015s	user 0.013s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5560,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:01.543097 15405 maintenance_manager.cc:419] P 8e712cc0207b4a7589bce39a6c8db3e6: Scheduling MajorDeltaCompactionOp(745a3f4b44214931a951605644fa3076): perf score=1.000000
I20260812 06:17:01.691447 15314 maintenance_manager.cc:643] P 8e712cc0207b4a7589bce39a6c8db3e6: MajorDeltaCompactionOp(745a3f4b44214931a951605644fa3076) complete. Timing: real 0.148s	user 0.121s	sys 0.025s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774808,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":882,"lbm_read_time_us":11585,"lbm_reads_lt_1ms":573,"lbm_write_time_us":28412,"lbm_writes_lt_1ms":543,"mutex_wait_us":261,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":36864,"update_count":2500}
I20260812 06:17:01.692274 15405 maintenance_manager.cc:419] P 8e712cc0207b4a7589bce39a6c8db3e6: Scheduling FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076): perf score=11.118625
I20260812 06:17:01.723932 15314 maintenance_manager.cc:643] P 8e712cc0207b4a7589bce39a6c8db3e6: FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076) complete. Timing: real 0.031s	user 0.013s	sys 0.016s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":13741,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:01.724414 15405 maintenance_manager.cc:419] P 8e712cc0207b4a7589bce39a6c8db3e6: Scheduling FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076): perf score=2.188937
I20260812 06:17:01.738739 15314 maintenance_manager.cc:643] P 8e712cc0207b4a7589bce39a6c8db3e6: FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076) complete. Timing: real 0.014s	user 0.006s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5267,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:01.739565 15405 maintenance_manager.cc:419] P 8e712cc0207b4a7589bce39a6c8db3e6: Scheduling FlushMRSOp(745a3f4b44214931a951605644fa3076): perf score=1.000000
I20260812 06:17:01.767475 15314 maintenance_manager.cc:643] P 8e712cc0207b4a7589bce39a6c8db3e6: FlushMRSOp(745a3f4b44214931a951605644fa3076) complete. Timing: real 0.028s	user 0.026s	sys 0.000s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":67,"dirs.run_cpu_time_us":238,"dirs.run_wall_time_us":1500,"drs_written":1,"lbm_read_time_us":74,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1569,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:01.768169 15405 maintenance_manager.cc:419] P 8e712cc0207b4a7589bce39a6c8db3e6: Scheduling LogGCOp(745a3f4b44214931a951605644fa3076): free 133477453 bytes of WAL
I20260812 06:17:01.768448 15314 log_reader.cc:385] T 745a3f4b44214931a951605644fa3076: removed 13 log segments from log reader
I20260812 06:17:01.768510 15314 log.cc:1079] T 745a3f4b44214931a951605644fa3076 P 8e712cc0207b4a7589bce39a6c8db3e6: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/745a3f4b44214931a951605644fa3076/wal-000000015 (ops 71-75)
I20260812 06:17:01.768548 15314 log.cc:1079] T 745a3f4b44214931a951605644fa3076 P 8e712cc0207b4a7589bce39a6c8db3e6: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/745a3f4b44214931a951605644fa3076/wal-000000016 (ops 76-80)
I20260812 06:17:01.768582 15314 log.cc:1079] T 745a3f4b44214931a951605644fa3076 P 8e712cc0207b4a7589bce39a6c8db3e6: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/745a3f4b44214931a951605644fa3076/wal-000000017 (ops 81-85)
I20260812 06:17:01.768613 15314 log.cc:1079] T 745a3f4b44214931a951605644fa3076 P 8e712cc0207b4a7589bce39a6c8db3e6: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/745a3f4b44214931a951605644fa3076/wal-000000018 (ops 86-90)
I20260812 06:17:01.768643 15314 log.cc:1079] T 745a3f4b44214931a951605644fa3076 P 8e712cc0207b4a7589bce39a6c8db3e6: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/745a3f4b44214931a951605644fa3076/wal-000000019 (ops 91-95)
I20260812 06:17:01.768669 15314 log.cc:1079] T 745a3f4b44214931a951605644fa3076 P 8e712cc0207b4a7589bce39a6c8db3e6: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/745a3f4b44214931a951605644fa3076/wal-000000020 (ops 96-100)
I20260812 06:17:01.768699 15314 log.cc:1079] T 745a3f4b44214931a951605644fa3076 P 8e712cc0207b4a7589bce39a6c8db3e6: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/745a3f4b44214931a951605644fa3076/wal-000000021 (ops 101-105)
I20260812 06:17:01.768728 15314 log.cc:1079] T 745a3f4b44214931a951605644fa3076 P 8e712cc0207b4a7589bce39a6c8db3e6: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/745a3f4b44214931a951605644fa3076/wal-000000022 (ops 106-110)
I20260812 06:17:01.768762 15314 log.cc:1079] T 745a3f4b44214931a951605644fa3076 P 8e712cc0207b4a7589bce39a6c8db3e6: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/745a3f4b44214931a951605644fa3076/wal-000000023 (ops 111-115)
I20260812 06:17:01.768792 15314 log.cc:1079] T 745a3f4b44214931a951605644fa3076 P 8e712cc0207b4a7589bce39a6c8db3e6: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/745a3f4b44214931a951605644fa3076/wal-000000024 (ops 116-120)
I20260812 06:17:01.768822 15314 log.cc:1079] T 745a3f4b44214931a951605644fa3076 P 8e712cc0207b4a7589bce39a6c8db3e6: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/745a3f4b44214931a951605644fa3076/wal-000000025 (ops 121-125)
I20260812 06:17:01.768849 15314 log.cc:1079] T 745a3f4b44214931a951605644fa3076 P 8e712cc0207b4a7589bce39a6c8db3e6: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/745a3f4b44214931a951605644fa3076/wal-000000026 (ops 126-130)
I20260812 06:17:01.768890 15314 log.cc:1079] T 745a3f4b44214931a951605644fa3076 P 8e712cc0207b4a7589bce39a6c8db3e6: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/745a3f4b44214931a951605644fa3076/wal-000000027 (ops 131-135)
I20260812 06:17:01.800850 15314 maintenance_manager.cc:643] P 8e712cc0207b4a7589bce39a6c8db3e6: LogGCOp(745a3f4b44214931a951605644fa3076) complete. Timing: real 0.032s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:17:01.801301 15405 maintenance_manager.cc:419] P 8e712cc0207b4a7589bce39a6c8db3e6: Scheduling UndoDeltaBlockGCOp(745a3f4b44214931a951605644fa3076): 482 bytes on disk
I20260812 06:17:01.801795 15314 maintenance_manager.cc:643] P 8e712cc0207b4a7589bce39a6c8db3e6: UndoDeltaBlockGCOp(745a3f4b44214931a951605644fa3076) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4}
I20260812 06:17:01.802390 15405 maintenance_manager.cc:419] P 8e712cc0207b4a7589bce39a6c8db3e6: Scheduling FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076): perf score=2.188937
I20260812 06:17:01.821003 15314 maintenance_manager.cc:643] P 8e712cc0207b4a7589bce39a6c8db3e6: FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076) complete. Timing: real 0.018s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4437,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:01.821471 15405 maintenance_manager.cc:419] P 8e712cc0207b4a7589bce39a6c8db3e6: Scheduling FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076): perf score=2.188937
I20260812 06:17:01.832846 15314 maintenance_manager.cc:643] P 8e712cc0207b4a7589bce39a6c8db3e6: FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4085,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:01.833477 15405 maintenance_manager.cc:419] P 8e712cc0207b4a7589bce39a6c8db3e6: Scheduling MajorDeltaCompactionOp(745a3f4b44214931a951605644fa3076): perf score=1.000000
I20260812 06:17:01.997890 15314 maintenance_manager.cc:643] P 8e712cc0207b4a7589bce39a6c8db3e6: MajorDeltaCompactionOp(745a3f4b44214931a951605644fa3076) complete. Timing: real 0.164s	user 0.119s	sys 0.042s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877329,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":3074,"lbm_read_time_us":10707,"lbm_reads_lt_1ms":674,"lbm_write_time_us":34804,"lbm_writes_lt_1ms":643,"mutex_wait_us":2131,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":9600,"thread_start_us":95,"threads_started":1,"update_count":3000}
I20260812 06:17:01.998754 15405 maintenance_manager.cc:419] P 8e712cc0207b4a7589bce39a6c8db3e6: Scheduling FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076): perf score=14.095187
I20260812 06:17:02.044584 15314 maintenance_manager.cc:643] P 8e712cc0207b4a7589bce39a6c8db3e6: FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076) complete. Timing: real 0.046s	user 0.015s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18696,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:02.045264 15405 maintenance_manager.cc:419] P 8e712cc0207b4a7589bce39a6c8db3e6: Scheduling FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076): perf score=2.188937
I20260812 06:17:02.061149 15314 maintenance_manager.cc:643] P 8e712cc0207b4a7589bce39a6c8db3e6: FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076) complete. Timing: real 0.016s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5804,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:02.061676 15405 maintenance_manager.cc:419] P 8e712cc0207b4a7589bce39a6c8db3e6: Scheduling MajorDeltaCompactionOp(745a3f4b44214931a951605644fa3076): perf score=1.000000
I20260812 06:17:02.227427 15314 maintenance_manager.cc:643] P 8e712cc0207b4a7589bce39a6c8db3e6: MajorDeltaCompactionOp(745a3f4b44214931a951605644fa3076) complete. Timing: real 0.166s	user 0.136s	sys 0.011s 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":627,"lbm_read_time_us":9469,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30083,"lbm_writes_lt_1ms":543,"mutex_wait_us":273,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2500}
I20260812 06:17:02.228080 15405 maintenance_manager.cc:419] P 8e712cc0207b4a7589bce39a6c8db3e6: Scheduling FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076): perf score=14.095187
I20260812 06:17:02.289268 15314 maintenance_manager.cc:643] P 8e712cc0207b4a7589bce39a6c8db3e6: FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076) complete. Timing: real 0.061s	user 0.035s	sys 0.007s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":19553,"lbm_writes_lt_1ms":403,"mutex_wait_us":1,"reinsert_count":0,"update_count":2000}
I20260812 06:17:02.289882 15405 maintenance_manager.cc:419] P 8e712cc0207b4a7589bce39a6c8db3e6: Scheduling FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076): perf score=2.188937
I20260812 06:17:02.300645 15314 maintenance_manager.cc:643] P 8e712cc0207b4a7589bce39a6c8db3e6: FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4016,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:02.301425 15405 maintenance_manager.cc:419] P 8e712cc0207b4a7589bce39a6c8db3e6: Scheduling MajorDeltaCompactionOp(745a3f4b44214931a951605644fa3076): perf score=1.000000
I20260812 06:17:02.485255 15314 maintenance_manager.cc:643] P 8e712cc0207b4a7589bce39a6c8db3e6: MajorDeltaCompactionOp(745a3f4b44214931a951605644fa3076) complete. Timing: real 0.184s	user 0.128s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":195,"lbm_read_time_us":11772,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31481,"lbm_writes_lt_1ms":543,"mutex_wait_us":28,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":32000,"update_count":2500}
I20260812 06:17:02.485980 15405 maintenance_manager.cc:419] P 8e712cc0207b4a7589bce39a6c8db3e6: Scheduling FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076): perf score=14.095187
I20260812 06:17:02.530901 15314 maintenance_manager.cc:643] P 8e712cc0207b4a7589bce39a6c8db3e6: FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076) complete. Timing: real 0.045s	user 0.033s	sys 0.011s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19233,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:02.531623 15405 maintenance_manager.cc:419] P 8e712cc0207b4a7589bce39a6c8db3e6: Scheduling MajorDeltaCompactionOp(745a3f4b44214931a951605644fa3076): perf score=1.000000
I20260812 06:17:02.684854 15314 maintenance_manager.cc:643] P 8e712cc0207b4a7589bce39a6c8db3e6: MajorDeltaCompactionOp(745a3f4b44214931a951605644fa3076) complete. Timing: real 0.153s	user 0.098s	sys 0.053s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672157,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":256,"lbm_read_time_us":11181,"lbm_reads_lt_1ms":467,"lbm_write_time_us":25353,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12160,"update_count":2000}
I20260812 06:17:02.686480 15405 maintenance_manager.cc:419] P 8e712cc0207b4a7589bce39a6c8db3e6: Scheduling FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076): perf score=10.126437
I20260812 06:17:02.722422 15314 maintenance_manager.cc:643] P 8e712cc0207b4a7589bce39a6c8db3e6: FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076) complete. Timing: real 0.036s	user 0.014s	sys 0.021s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14642,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:02.723100 15405 maintenance_manager.cc:419] P 8e712cc0207b4a7589bce39a6c8db3e6: Scheduling FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076): perf score=2.188937
I20260812 06:17:02.749400 15314 maintenance_manager.cc:643] P 8e712cc0207b4a7589bce39a6c8db3e6: FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076) complete. Timing: real 0.026s	user 0.006s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5845,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:02.749902 15405 maintenance_manager.cc:419] P 8e712cc0207b4a7589bce39a6c8db3e6: Scheduling FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076): perf score=2.188937
I20260812 06:17:02.760764 15314 maintenance_manager.cc:643] P 8e712cc0207b4a7589bce39a6c8db3e6: FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4089,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:02.761256 15405 maintenance_manager.cc:419] P 8e712cc0207b4a7589bce39a6c8db3e6: Scheduling MajorDeltaCompactionOp(745a3f4b44214931a951605644fa3076): perf score=1.000000
I20260812 06:17:02.930168 15314 maintenance_manager.cc:643] P 8e712cc0207b4a7589bce39a6c8db3e6: MajorDeltaCompactionOp(745a3f4b44214931a951605644fa3076) complete. Timing: real 0.169s	user 0.123s	sys 0.045s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774808,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":288,"lbm_read_time_us":11485,"lbm_reads_lt_1ms":573,"lbm_write_time_us":28623,"lbm_writes_lt_1ms":543,"mutex_wait_us":94,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12800,"update_count":2500}
I20260812 06:17:02.933951 15405 maintenance_manager.cc:419] P 8e712cc0207b4a7589bce39a6c8db3e6: Scheduling FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076): perf score=14.095187
I20260812 06:17:02.982299 15314 maintenance_manager.cc:643] P 8e712cc0207b4a7589bce39a6c8db3e6: FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076) complete. Timing: real 0.048s	user 0.034s	sys 0.014s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21360,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:02.982825 15405 maintenance_manager.cc:419] P 8e712cc0207b4a7589bce39a6c8db3e6: Scheduling FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076): perf score=2.188937
I20260812 06:17:02.994805 15314 maintenance_manager.cc:643] P 8e712cc0207b4a7589bce39a6c8db3e6: FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4513,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:02.995241 15405 maintenance_manager.cc:419] P 8e712cc0207b4a7589bce39a6c8db3e6: Scheduling MajorDeltaCompactionOp(745a3f4b44214931a951605644fa3076): perf score=1.000000
I20260812 06:17:03.152400 15314 maintenance_manager.cc:643] P 8e712cc0207b4a7589bce39a6c8db3e6: MajorDeltaCompactionOp(745a3f4b44214931a951605644fa3076) complete. Timing: real 0.157s	user 0.120s	sys 0.028s 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":538,"lbm_read_time_us":9881,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30442,"lbm_writes_lt_1ms":543,"mutex_wait_us":24,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13824,"update_count":2500}
I20260812 06:17:03.153095 15405 maintenance_manager.cc:419] P 8e712cc0207b4a7589bce39a6c8db3e6: Scheduling FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076): perf score=14.095187
I20260812 06:17:03.212855 15314 maintenance_manager.cc:643] P 8e712cc0207b4a7589bce39a6c8db3e6: FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076) complete. Timing: real 0.060s	user 0.035s	sys 0.015s Metrics: {"bytes_written":16409897,"delete_count":0,"lbm_write_time_us":26193,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:17:03.213394 15405 maintenance_manager.cc:419] P 8e712cc0207b4a7589bce39a6c8db3e6: Scheduling FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076): perf score=2.188937
I20260812 06:17:03.226174 15314 maintenance_manager.cc:643] P 8e712cc0207b4a7589bce39a6c8db3e6: FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076) complete. Timing: real 0.013s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4534,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:03.226836 15405 maintenance_manager.cc:419] P 8e712cc0207b4a7589bce39a6c8db3e6: Scheduling FlushMRSOp(745a3f4b44214931a951605644fa3076): perf score=1.000000
I20260812 06:17:03.279521 15314 maintenance_manager.cc:643] P 8e712cc0207b4a7589bce39a6c8db3e6: FlushMRSOp(745a3f4b44214931a951605644fa3076) complete. Timing: real 0.052s	user 0.036s	sys 0.002s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":97,"dirs.run_cpu_time_us":302,"dirs.run_wall_time_us":17622,"drs_written":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2198,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:03.280682 15405 maintenance_manager.cc:419] P 8e712cc0207b4a7589bce39a6c8db3e6: Scheduling LogGCOp(745a3f4b44214931a951605644fa3076): free 124257506 bytes of WAL
I20260812 06:17:03.280987 15314 log_reader.cc:385] T 745a3f4b44214931a951605644fa3076: removed 12 log segments from log reader
I20260812 06:17:03.281068 15314 log.cc:1079] T 745a3f4b44214931a951605644fa3076 P 8e712cc0207b4a7589bce39a6c8db3e6: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/745a3f4b44214931a951605644fa3076/wal-000000028 (ops 136-140)
I20260812 06:17:03.281157 15314 log.cc:1079] T 745a3f4b44214931a951605644fa3076 P 8e712cc0207b4a7589bce39a6c8db3e6: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/745a3f4b44214931a951605644fa3076/wal-000000029 (ops 141-145)
I20260812 06:17:03.281224 15314 log.cc:1079] T 745a3f4b44214931a951605644fa3076 P 8e712cc0207b4a7589bce39a6c8db3e6: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/745a3f4b44214931a951605644fa3076/wal-000000030 (ops 146-150)
I20260812 06:17:03.281298 15314 log.cc:1079] T 745a3f4b44214931a951605644fa3076 P 8e712cc0207b4a7589bce39a6c8db3e6: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/745a3f4b44214931a951605644fa3076/wal-000000031 (ops 151-155)
I20260812 06:17:03.281375 15314 log.cc:1079] T 745a3f4b44214931a951605644fa3076 P 8e712cc0207b4a7589bce39a6c8db3e6: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/745a3f4b44214931a951605644fa3076/wal-000000032 (ops 156-160)
I20260812 06:17:03.281419 15314 log.cc:1079] T 745a3f4b44214931a951605644fa3076 P 8e712cc0207b4a7589bce39a6c8db3e6: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/745a3f4b44214931a951605644fa3076/wal-000000033 (ops 161-165)
I20260812 06:17:03.281457 15314 log.cc:1079] T 745a3f4b44214931a951605644fa3076 P 8e712cc0207b4a7589bce39a6c8db3e6: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/745a3f4b44214931a951605644fa3076/wal-000000034 (ops 166-170)
I20260812 06:17:03.281498 15314 log.cc:1079] T 745a3f4b44214931a951605644fa3076 P 8e712cc0207b4a7589bce39a6c8db3e6: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/745a3f4b44214931a951605644fa3076/wal-000000035 (ops 171-175)
I20260812 06:17:03.281539 15314 log.cc:1079] T 745a3f4b44214931a951605644fa3076 P 8e712cc0207b4a7589bce39a6c8db3e6: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/745a3f4b44214931a951605644fa3076/wal-000000036 (ops 176-180)
I20260812 06:17:03.281579 15314 log.cc:1079] T 745a3f4b44214931a951605644fa3076 P 8e712cc0207b4a7589bce39a6c8db3e6: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/745a3f4b44214931a951605644fa3076/wal-000000037 (ops 181-185)
I20260812 06:17:03.281620 15314 log.cc:1079] T 745a3f4b44214931a951605644fa3076 P 8e712cc0207b4a7589bce39a6c8db3e6: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/745a3f4b44214931a951605644fa3076/wal-000000038 (ops 186-190)
I20260812 06:17:03.281661 15314 log.cc:1079] T 745a3f4b44214931a951605644fa3076 P 8e712cc0207b4a7589bce39a6c8db3e6: Deleting log segment in path: /tmp/dist-test-taskDZTyyE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412910501-14797-0/minicluster-data/ts-0-root/wals/745a3f4b44214931a951605644fa3076/wal-000000039 (ops 191-194)
I20260812 06:17:03.308220 15314 maintenance_manager.cc:643] P 8e712cc0207b4a7589bce39a6c8db3e6: LogGCOp(745a3f4b44214931a951605644fa3076) complete. Timing: real 0.027s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:17:03.308701 15405 maintenance_manager.cc:419] P 8e712cc0207b4a7589bce39a6c8db3e6: Scheduling FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076): perf score=6.157687
I20260812 06:17:03.374702 14797 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.831s	user 1.867s	sys 0.111s
I20260812 06:17:03.376794 15314 maintenance_manager.cc:643] P 8e712cc0207b4a7589bce39a6c8db3e6: FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076) complete. Timing: real 0.068s	user 0.013s	sys 0.016s Metrics: {"bytes_written":8205080,"delete_count":0,"lbm_write_time_us":13347,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:17:03.377265 15405 maintenance_manager.cc:419] P 8e712cc0207b4a7589bce39a6c8db3e6: Scheduling FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076): perf score=2.188937
I20260812 06:17:03.478488 15314 maintenance_manager.cc:643] P 8e712cc0207b4a7589bce39a6c8db3e6: FlushDeltaMemStoresOp(745a3f4b44214931a951605644fa3076) complete. Timing: real 0.101s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4068,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:03.479102 15405 maintenance_manager.cc:419] P 8e712cc0207b4a7589bce39a6c8db3e6: Scheduling MajorDeltaCompactionOp(745a3f4b44214931a951605644fa3076): perf score=1.000000
I20260812 06:17:03.485148 14797 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.110s	user 0.001s	sys 0.000s
I20260812 06:17:03.485761 14797 tablet_server.cc:179] TabletServer@127.14.115.65:0 shutting down...
I20260812 06:17:03.680143 15314 maintenance_manager.cc:643] P 8e712cc0207b4a7589bce39a6c8db3e6: MajorDeltaCompactionOp(745a3f4b44214931a951605644fa3076) complete. Timing: real 0.201s	user 0.125s	sys 0.040s Metrics: {"cfile_cache_hit":733,"cfile_cache_hit_bytes":32979630,"cfile_cache_miss":101,"cfile_cache_miss_bytes":4102531,"cfile_init":3,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":935,"lbm_read_time_us":1804,"lbm_reads_lt_1ms":113,"lbm_write_time_us":36561,"lbm_writes_lt_1ms":843,"mutex_wait_us":1,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":1280,"thread_start_us":406,"threads_started":6,"update_count":4000}
I20260812 06:17:03.682776 14797 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:03.683301 14797 tablet_replica.cc:333] T 745a3f4b44214931a951605644fa3076 P 8e712cc0207b4a7589bce39a6c8db3e6: stopping tablet replica
I20260812 06:17:03.683516 14797 raft_consensus.cc:2243] T 745a3f4b44214931a951605644fa3076 P 8e712cc0207b4a7589bce39a6c8db3e6 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:03.683712 14797 raft_consensus.cc:2272] T 745a3f4b44214931a951605644fa3076 P 8e712cc0207b4a7589bce39a6c8db3e6 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:03.698112 14797 tablet_server.cc:196] TabletServer@127.14.115.65:0 shutdown complete.
I20260812 06:17:03.921677 14797 master.cc:562] Master@127.14.115.126:37217 shutting down...
I20260812 06:17:03.925751 14797 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 1a0145d37def47469c9821d14fdc5b90 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:03.925971 14797 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 1a0145d37def47469c9821d14fdc5b90 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:03.926028 14797 tablet_replica.cc:333] T 00000000000000000000000000000000 P 1a0145d37def47469c9821d14fdc5b90: stopping tablet replica
I20260812 06:17:03.943033 14797 master.cc:584] Master@127.14.115.126:37217 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5685 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11112 ms total)

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