[==========] 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:20:24.872249  1664 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.1.160.62:38203
I20260812 06:20:24.873345  1664 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:20:24.874073  1664 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:24.880489  1674 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:20:24.880617  1664 server_base.cc:1061] running on GCE node
W20260812 06:20:24.880785  1671 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:20:24.880492  1672 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:20:24.881386  1664 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:24.881541  1664 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:20:24.881640  1664 hybrid_clock.cc:648] HybridClock initialized: now 1786515624881637 us; error 0 us; skew 500 ppm
I20260812 06:20:24.883595  1664 webserver.cc:533] Webserver started at http://127.1.160.62:45835/ using document root <none> and password file <none>
I20260812 06:20:24.884214  1664 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:24.884315  1664 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:24.884596  1664 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:24.886399  1664 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624860936-1664-0/minicluster-data/master-0-root/instance:
uuid: "b7e839a726a34191a4d5d8858137a351"
format_stamp: "Formatted at 2026-08-12 06:20:24 on dist-test-slave-njxd"
I20260812 06:20:24.890100  1664 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.004s	sys 0.000s
I20260812 06:20:24.892270  1680 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:20:24.893349  1664 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:20:24.893507  1664 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624860936-1664-0/minicluster-data/master-0-root
uuid: "b7e839a726a34191a4d5d8858137a351"
format_stamp: "Formatted at 2026-08-12 06:20:24 on dist-test-slave-njxd"
I20260812 06:20:24.893671  1664 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624860936-1664-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624860936-1664-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624860936-1664-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:20:24.909502  1664 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:24.910348  1664 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:20:24.910557  1664 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:24.918656  1738 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.1.160.62:38203 every 8 connection(s)
I20260812 06:20:24.918672  1664 rpc_server.cc:307] RPC server started. Bound to: 127.1.160.62:38203
I20260812 06:20:24.920989  1740 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:20:24.926782  1740 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P b7e839a726a34191a4d5d8858137a351: Bootstrap starting.
I20260812 06:20:24.929173  1740 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P b7e839a726a34191a4d5d8858137a351: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:24.930197  1740 log.cc:826] T 00000000000000000000000000000000 P b7e839a726a34191a4d5d8858137a351: Log is configured to *not* fsync() on all Append() calls
I20260812 06:20:24.931906  1740 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P b7e839a726a34191a4d5d8858137a351: No bootstrap required, opened a new log
I20260812 06:20:24.934676  1740 raft_consensus.cc:359] T 00000000000000000000000000000000 P b7e839a726a34191a4d5d8858137a351 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b7e839a726a34191a4d5d8858137a351" member_type: VOTER }
I20260812 06:20:24.934845  1740 raft_consensus.cc:385] T 00000000000000000000000000000000 P b7e839a726a34191a4d5d8858137a351 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:24.934887  1740 raft_consensus.cc:740] T 00000000000000000000000000000000 P b7e839a726a34191a4d5d8858137a351 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: b7e839a726a34191a4d5d8858137a351, State: Initialized, Role: FOLLOWER
I20260812 06:20:24.935420  1740 consensus_queue.cc:260] T 00000000000000000000000000000000 P b7e839a726a34191a4d5d8858137a351 [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: "b7e839a726a34191a4d5d8858137a351" member_type: VOTER }
I20260812 06:20:24.935551  1740 raft_consensus.cc:399] T 00000000000000000000000000000000 P b7e839a726a34191a4d5d8858137a351 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:24.935599  1740 raft_consensus.cc:493] T 00000000000000000000000000000000 P b7e839a726a34191a4d5d8858137a351 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:24.935681  1740 raft_consensus.cc:3060] T 00000000000000000000000000000000 P b7e839a726a34191a4d5d8858137a351 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:24.936451  1740 raft_consensus.cc:515] T 00000000000000000000000000000000 P b7e839a726a34191a4d5d8858137a351 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b7e839a726a34191a4d5d8858137a351" member_type: VOTER }
I20260812 06:20:24.936848  1740 leader_election.cc:304] T 00000000000000000000000000000000 P b7e839a726a34191a4d5d8858137a351 [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: b7e839a726a34191a4d5d8858137a351; no voters: 
I20260812 06:20:24.937129  1740 leader_election.cc:290] T 00000000000000000000000000000000 P b7e839a726a34191a4d5d8858137a351 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:24.937289  1743 raft_consensus.cc:2804] T 00000000000000000000000000000000 P b7e839a726a34191a4d5d8858137a351 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:24.937549  1743 raft_consensus.cc:697] T 00000000000000000000000000000000 P b7e839a726a34191a4d5d8858137a351 [term 1 LEADER]: Becoming Leader. State: Replica: b7e839a726a34191a4d5d8858137a351, State: Running, Role: LEADER
I20260812 06:20:24.938005  1743 consensus_queue.cc:237] T 00000000000000000000000000000000 P b7e839a726a34191a4d5d8858137a351 [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: "b7e839a726a34191a4d5d8858137a351" member_type: VOTER }
I20260812 06:20:24.938274  1740 sys_catalog.cc:565] T 00000000000000000000000000000000 P b7e839a726a34191a4d5d8858137a351 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:20:24.940057  1745 sys_catalog.cc:455] T 00000000000000000000000000000000 P b7e839a726a34191a4d5d8858137a351 [sys.catalog]: SysCatalogTable state changed. Reason: New leader b7e839a726a34191a4d5d8858137a351. Latest consensus state: current_term: 1 leader_uuid: "b7e839a726a34191a4d5d8858137a351" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b7e839a726a34191a4d5d8858137a351" member_type: VOTER } }
I20260812 06:20:24.940044  1744 sys_catalog.cc:455] T 00000000000000000000000000000000 P b7e839a726a34191a4d5d8858137a351 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "b7e839a726a34191a4d5d8858137a351" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b7e839a726a34191a4d5d8858137a351" member_type: VOTER } }
I20260812 06:20:24.940202  1744 sys_catalog.cc:458] T 00000000000000000000000000000000 P b7e839a726a34191a4d5d8858137a351 [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:24.940202  1745 sys_catalog.cc:458] T 00000000000000000000000000000000 P b7e839a726a34191a4d5d8858137a351 [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:24.940599  1664 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:20:24.942683  1762 catalog_manager.cc:1594] T 00000000000000000000000000000000 P b7e839a726a34191a4d5d8858137a351: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:20:24.942752  1762 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:20:24.942830  1759 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:20:24.943558  1759 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:20:24.948550  1759 catalog_manager.cc:1383] Generated new cluster ID: 32ad535ac5e54046853fa616cb803e48
I20260812 06:20:24.948633  1759 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:20:24.961318  1759 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:20:24.962297  1759 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:20:24.977201  1759 catalog_manager.cc:6092] T 00000000000000000000000000000000 P b7e839a726a34191a4d5d8858137a351: Generated new TSK 0
I20260812 06:20:24.978003  1759 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:20:25.005800  1664 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:25.008863  1768 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:20:25.008932  1767 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:20:25.008949  1770 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:20:25.009321  1664 server_base.cc:1061] running on GCE node
I20260812 06:20:25.009500  1664 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:25.009547  1664 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:20:25.009593  1664 hybrid_clock.cc:648] HybridClock initialized: now 1786515625009592 us; error 0 us; skew 500 ppm
I20260812 06:20:25.010594  1664 webserver.cc:533] Webserver started at http://127.1.160.1:34557/ using document root <none> and password file <none>
I20260812 06:20:25.010773  1664 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:25.010833  1664 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:25.010910  1664 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:25.011366  1664 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624860936-1664-0/minicluster-data/ts-0-root/instance:
uuid: "35cb7da96f224476b15f4a5e7442681e"
format_stamp: "Formatted at 2026-08-12 06:20:25 on dist-test-slave-njxd"
I20260812 06:20:25.013329  1664 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:20:25.014496  1775 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:20:25.014792  1664 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:20:25.014863  1664 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624860936-1664-0/minicluster-data/ts-0-root
uuid: "35cb7da96f224476b15f4a5e7442681e"
format_stamp: "Formatted at 2026-08-12 06:20:25 on dist-test-slave-njxd"
I20260812 06:20:25.014956  1664 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624860936-1664-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624860936-1664-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624860936-1664-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:20:25.023778  1664 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:25.024267  1664 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:25.024803  1664 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:20:25.025755  1664 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:20:25.025810  1664 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:25.025880  1664 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:20:25.025920  1664 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:25.032938  1664 rpc_server.cc:307] RPC server started. Bound to: 127.1.160.1:33289
I20260812 06:20:25.032959  1846 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.1.160.1:33289 every 8 connection(s)
I20260812 06:20:25.050925  1848 heartbeater.cc:344] Connected to a master server at 127.1.160.62:38203
I20260812 06:20:25.051239  1848 heartbeater.cc:461] Registering TS with master...
I20260812 06:20:25.051748  1848 heartbeater.cc:507] Master 127.1.160.62:38203 requested a full tablet report, sending...
I20260812 06:20:25.053253  1702 ts_manager.cc:194] Registered new tserver with Master: 35cb7da96f224476b15f4a5e7442681e (127.1.160.1:33289)
I20260812 06:20:25.053805  1664 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.020119471s
I20260812 06:20:25.054625  1702 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:55642
I20260812 06:20:25.064170  1702 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:55644:
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:20:25.084645  1807 tablet_service.cc:1511] Processing CreateTablet for tablet 2b81f8f488044a74b1336e29cb725d7e (DEFAULT_TABLE table=heavy-update-compaction-test [id=5fcca813ee5a4201b6138e10fdee2c3b]), partition=
I20260812 06:20:25.085130  1807 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 2b81f8f488044a74b1336e29cb725d7e. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:20:25.087569  1862 tablet_bootstrap.cc:492] T 2b81f8f488044a74b1336e29cb725d7e P 35cb7da96f224476b15f4a5e7442681e: Bootstrap starting.
I20260812 06:20:25.088848  1862 tablet_bootstrap.cc:654] T 2b81f8f488044a74b1336e29cb725d7e P 35cb7da96f224476b15f4a5e7442681e: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:25.090819  1862 tablet_bootstrap.cc:492] T 2b81f8f488044a74b1336e29cb725d7e P 35cb7da96f224476b15f4a5e7442681e: No bootstrap required, opened a new log
I20260812 06:20:25.090951  1862 ts_tablet_manager.cc:1403] T 2b81f8f488044a74b1336e29cb725d7e P 35cb7da96f224476b15f4a5e7442681e: Time spent bootstrapping tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:20:25.091583  1862 raft_consensus.cc:359] T 2b81f8f488044a74b1336e29cb725d7e P 35cb7da96f224476b15f4a5e7442681e [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "35cb7da96f224476b15f4a5e7442681e" member_type: VOTER last_known_addr { host: "127.1.160.1" port: 33289 } }
I20260812 06:20:25.091727  1862 raft_consensus.cc:385] T 2b81f8f488044a74b1336e29cb725d7e P 35cb7da96f224476b15f4a5e7442681e [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:25.091773  1862 raft_consensus.cc:740] T 2b81f8f488044a74b1336e29cb725d7e P 35cb7da96f224476b15f4a5e7442681e [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 35cb7da96f224476b15f4a5e7442681e, State: Initialized, Role: FOLLOWER
I20260812 06:20:25.091985  1862 consensus_queue.cc:260] T 2b81f8f488044a74b1336e29cb725d7e P 35cb7da96f224476b15f4a5e7442681e [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: "35cb7da96f224476b15f4a5e7442681e" member_type: VOTER last_known_addr { host: "127.1.160.1" port: 33289 } }
I20260812 06:20:25.092135  1862 raft_consensus.cc:399] T 2b81f8f488044a74b1336e29cb725d7e P 35cb7da96f224476b15f4a5e7442681e [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:25.092202  1862 raft_consensus.cc:493] T 2b81f8f488044a74b1336e29cb725d7e P 35cb7da96f224476b15f4a5e7442681e [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:25.092293  1862 raft_consensus.cc:3060] T 2b81f8f488044a74b1336e29cb725d7e P 35cb7da96f224476b15f4a5e7442681e [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:25.093405  1862 raft_consensus.cc:515] T 2b81f8f488044a74b1336e29cb725d7e P 35cb7da96f224476b15f4a5e7442681e [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "35cb7da96f224476b15f4a5e7442681e" member_type: VOTER last_known_addr { host: "127.1.160.1" port: 33289 } }
I20260812 06:20:25.093616  1862 leader_election.cc:304] T 2b81f8f488044a74b1336e29cb725d7e P 35cb7da96f224476b15f4a5e7442681e [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: 35cb7da96f224476b15f4a5e7442681e; no voters: 
I20260812 06:20:25.093866  1862 leader_election.cc:290] T 2b81f8f488044a74b1336e29cb725d7e P 35cb7da96f224476b15f4a5e7442681e [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:25.094012  1864 raft_consensus.cc:2804] T 2b81f8f488044a74b1336e29cb725d7e P 35cb7da96f224476b15f4a5e7442681e [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:25.094292  1862 ts_tablet_manager.cc:1434] T 2b81f8f488044a74b1336e29cb725d7e P 35cb7da96f224476b15f4a5e7442681e: Time spent starting tablet: real 0.003s	user 0.004s	sys 0.000s
I20260812 06:20:25.094515  1848 heartbeater.cc:499] Master 127.1.160.62:38203 was elected leader, sending a full tablet report...
I20260812 06:20:25.094302  1864 raft_consensus.cc:697] T 2b81f8f488044a74b1336e29cb725d7e P 35cb7da96f224476b15f4a5e7442681e [term 1 LEADER]: Becoming Leader. State: Replica: 35cb7da96f224476b15f4a5e7442681e, State: Running, Role: LEADER
I20260812 06:20:25.095012  1864 consensus_queue.cc:237] T 2b81f8f488044a74b1336e29cb725d7e P 35cb7da96f224476b15f4a5e7442681e [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: "35cb7da96f224476b15f4a5e7442681e" member_type: VOTER last_known_addr { host: "127.1.160.1" port: 33289 } }
I20260812 06:20:25.098217  1702 catalog_manager.cc:5719] T 2b81f8f488044a74b1336e29cb725d7e P 35cb7da96f224476b15f4a5e7442681e reported cstate change: term changed from 0 to 1, leader changed from <none> to 35cb7da96f224476b15f4a5e7442681e (127.1.160.1). New cstate: current_term: 1 leader_uuid: "35cb7da96f224476b15f4a5e7442681e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "35cb7da96f224476b15f4a5e7442681e" member_type: VOTER last_known_addr { host: "127.1.160.1" port: 33289 } health_report { overall_health: HEALTHY } } }
I20260812 06:20:25.164259  1664 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.056s	user 0.021s	sys 0.004s
I20260812 06:20:25.284269  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling FlushMRSOp(2b81f8f488044a74b1336e29cb725d7e): perf score=15.086190
I20260812 06:20:25.430382  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: FlushMRSOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.146s	user 0.117s	sys 0.028s Metrics: {"bytes_written":8615323,"cfile_init":1,"compiler_manager_pool.queue_time_us":269,"delete_count":0,"dirs.queue_time_us":75,"dirs.run_cpu_time_us":229,"dirs.run_wall_time_us":1184,"drs_written":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4,"lbm_write_time_us":35624,"lbm_writes_lt_1ms":567,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"thread_start_us":168,"threads_started":1,"update_count":1050}
I20260812 06:20:25.432161  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling LogGCOp(2b81f8f488044a74b1336e29cb725d7e): free 8725963 bytes of WAL
I20260812 06:20:25.432538  1780 log_reader.cc:385] T 2b81f8f488044a74b1336e29cb725d7e: removed 1 log segments from log reader
I20260812 06:20:25.432632  1780 log.cc:1079] T 2b81f8f488044a74b1336e29cb725d7e P 35cb7da96f224476b15f4a5e7442681e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/2b81f8f488044a74b1336e29cb725d7e/wal-000000001 (ops 1-6)
I20260812 06:20:25.435393  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: LogGCOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:20:25.435959  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e): perf score=2.188937
I20260812 06:20:25.457602  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.021s	user 0.008s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6490,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:25.458236  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling UndoDeltaBlockGCOp(2b81f8f488044a74b1336e29cb725d7e): 12308958 bytes on disk
I20260812 06:20:25.458866  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: UndoDeltaBlockGCOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4}
I20260812 06:20:25.459323  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling MajorDeltaCompactionOp(2b81f8f488044a74b1336e29cb725d7e): perf score=1.000000
I20260812 06:20:25.594610  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: MajorDeltaCompactionOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.135s	user 0.095s	sys 0.031s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16528891,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":300,"lbm_read_time_us":7171,"lbm_reads_lt_1ms":360,"lbm_write_time_us":25358,"lbm_writes_lt_1ms":343,"mutex_wait_us":45,"peak_mem_usage":38262756,"reinsert_count":0,"thread_start_us":341,"threads_started":5,"update_count":1500}
I20260812 06:20:25.595252  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e): perf score=10.126437
I20260812 06:20:25.644971  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.050s	user 0.028s	sys 0.013s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":19137,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:20:25.645535  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e): perf score=2.188937
I20260812 06:20:25.661058  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5967,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:25.661778  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling MajorDeltaCompactionOp(2b81f8f488044a74b1336e29cb725d7e): perf score=1.000000
I20260812 06:20:25.790412  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: MajorDeltaCompactionOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.128s	user 0.107s	sys 0.021s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":779,"lbm_read_time_us":8578,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24888,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":18560,"update_count":2000}
I20260812 06:20:25.790964  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e): perf score=10.126437
I20260812 06:20:25.844558  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.053s	user 0.031s	sys 0.016s Metrics: {"bytes_written":12307494,"delete_count":0,"lbm_write_time_us":17251,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:25.845211  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e): perf score=2.188937
I20260812 06:20:25.861701  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.016s	user 0.016s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6084,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:25.862353  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling MajorDeltaCompactionOp(2b81f8f488044a74b1336e29cb725d7e): perf score=1.000000
I20260812 06:20:26.025748  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: MajorDeltaCompactionOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.163s	user 0.091s	sys 0.064s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631315,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":160,"lbm_read_time_us":11631,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25614,"lbm_writes_lt_1ms":443,"mutex_wait_us":100,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:20:26.026453  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e): perf score=10.126437
I20260812 06:20:26.078305  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.052s	user 0.027s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20192,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:20:26.078955  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e): perf score=2.188937
I20260812 06:20:26.090546  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.011s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4206,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:26.091178  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling MajorDeltaCompactionOp(2b81f8f488044a74b1336e29cb725d7e): perf score=1.000000
I20260812 06:20:26.224169  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: MajorDeltaCompactionOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.133s	user 0.105s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":477,"lbm_read_time_us":8517,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26975,"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:20:26.224852  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e): perf score=10.126437
I20260812 06:20:26.274853  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.050s	user 0.033s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":23495,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:20:26.275408  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e): perf score=2.188937
I20260812 06:20:26.287761  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4622,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:26.288239  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling MajorDeltaCompactionOp(2b81f8f488044a74b1336e29cb725d7e): perf score=1.000000
I20260812 06:20:26.425925  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: MajorDeltaCompactionOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.137s	user 0.108s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":703,"lbm_read_time_us":8978,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27857,"lbm_writes_lt_1ms":443,"mutex_wait_us":50,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:20:26.426795  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e): perf score=10.126437
I20260812 06:20:26.475857  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.049s	user 0.028s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18520,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:26.476446  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e): perf score=2.188937
I20260812 06:20:26.490226  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.014s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5102,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:26.490800  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling MajorDeltaCompactionOp(2b81f8f488044a74b1336e29cb725d7e): perf score=1.000000
I20260812 06:20:26.636107  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: MajorDeltaCompactionOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.144s	user 0.100s	sys 0.044s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":63,"lbm_read_time_us":9181,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25045,"lbm_writes_lt_1ms":443,"mutex_wait_us":22,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6912,"update_count":2000}
I20260812 06:20:26.639788  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e): perf score=11.118625
I20260812 06:20:26.682566  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.043s	user 0.038s	sys 0.004s Metrics: {"bytes_written":12512611,"delete_count":0,"lbm_write_time_us":18949,"lbm_writes_lt_1ms":308,"reinsert_count":0,"update_count":1525}
I20260812 06:20:26.683056  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e): perf score=2.188937
I20260812 06:20:26.694401  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":3897534,"delete_count":0,"lbm_write_time_us":4047,"lbm_writes_lt_1ms":98,"reinsert_count":0,"update_count":475}
I20260812 06:20:26.694897  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling MajorDeltaCompactionOp(2b81f8f488044a74b1336e29cb725d7e): perf score=1.000000
I20260812 06:20:26.832470  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: MajorDeltaCompactionOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.137s	user 0.101s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631308,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":292,"lbm_read_time_us":9960,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27807,"lbm_writes_lt_1ms":443,"mutex_wait_us":97,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":2000}
I20260812 06:20:26.833201  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e): perf score=10.126437
I20260812 06:20:26.879843  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.046s	user 0.020s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16711,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:26.880452  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e): perf score=2.188937
I20260812 06:20:26.891973  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4156,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:26.892618  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling FlushMRSOp(2b81f8f488044a74b1336e29cb725d7e): perf score=1.000000
I20260812 06:20:26.922518  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: FlushMRSOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.030s	user 0.023s	sys 0.006s Metrics: {"bytes_written":1275444,"cfile_init":1,"dirs.queue_time_us":68,"dirs.run_cpu_time_us":246,"dirs.run_wall_time_us":1450,"drs_written":1,"lbm_read_time_us":78,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2056,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31,"spinlock_wait_cycles":896}
I20260812 06:20:26.923372  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling LogGCOp(2b81f8f488044a74b1336e29cb725d7e): free 136275167 bytes of WAL
I20260812 06:20:26.923636  1780 log_reader.cc:385] T 2b81f8f488044a74b1336e29cb725d7e: removed 13 log segments from log reader
I20260812 06:20:26.923681  1780 log.cc:1079] T 2b81f8f488044a74b1336e29cb725d7e P 35cb7da96f224476b15f4a5e7442681e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/2b81f8f488044a74b1336e29cb725d7e/wal-000000002 (ops 7-11)
I20260812 06:20:26.923733  1780 log.cc:1079] T 2b81f8f488044a74b1336e29cb725d7e P 35cb7da96f224476b15f4a5e7442681e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/2b81f8f488044a74b1336e29cb725d7e/wal-000000003 (ops 12-16)
I20260812 06:20:26.923784  1780 log.cc:1079] T 2b81f8f488044a74b1336e29cb725d7e P 35cb7da96f224476b15f4a5e7442681e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/2b81f8f488044a74b1336e29cb725d7e/wal-000000004 (ops 17-21)
I20260812 06:20:26.923837  1780 log.cc:1079] T 2b81f8f488044a74b1336e29cb725d7e P 35cb7da96f224476b15f4a5e7442681e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/2b81f8f488044a74b1336e29cb725d7e/wal-000000005 (ops 22-26)
I20260812 06:20:26.923897  1780 log.cc:1079] T 2b81f8f488044a74b1336e29cb725d7e P 35cb7da96f224476b15f4a5e7442681e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/2b81f8f488044a74b1336e29cb725d7e/wal-000000006 (ops 27-31)
I20260812 06:20:26.923939  1780 log.cc:1079] T 2b81f8f488044a74b1336e29cb725d7e P 35cb7da96f224476b15f4a5e7442681e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/2b81f8f488044a74b1336e29cb725d7e/wal-000000007 (ops 32-36)
I20260812 06:20:26.923997  1780 log.cc:1079] T 2b81f8f488044a74b1336e29cb725d7e P 35cb7da96f224476b15f4a5e7442681e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/2b81f8f488044a74b1336e29cb725d7e/wal-000000008 (ops 37-41)
I20260812 06:20:26.924036  1780 log.cc:1079] T 2b81f8f488044a74b1336e29cb725d7e P 35cb7da96f224476b15f4a5e7442681e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/2b81f8f488044a74b1336e29cb725d7e/wal-000000009 (ops 42-46)
I20260812 06:20:26.924088  1780 log.cc:1079] T 2b81f8f488044a74b1336e29cb725d7e P 35cb7da96f224476b15f4a5e7442681e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/2b81f8f488044a74b1336e29cb725d7e/wal-000000010 (ops 47-51)
I20260812 06:20:26.924125  1780 log.cc:1079] T 2b81f8f488044a74b1336e29cb725d7e P 35cb7da96f224476b15f4a5e7442681e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/2b81f8f488044a74b1336e29cb725d7e/wal-000000011 (ops 52-56)
I20260812 06:20:26.924165  1780 log.cc:1079] T 2b81f8f488044a74b1336e29cb725d7e P 35cb7da96f224476b15f4a5e7442681e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/2b81f8f488044a74b1336e29cb725d7e/wal-000000012 (ops 57-61)
I20260812 06:20:26.924203  1780 log.cc:1079] T 2b81f8f488044a74b1336e29cb725d7e P 35cb7da96f224476b15f4a5e7442681e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/2b81f8f488044a74b1336e29cb725d7e/wal-000000013 (ops 62-66)
I20260812 06:20:26.924242  1780 log.cc:1079] T 2b81f8f488044a74b1336e29cb725d7e P 35cb7da96f224476b15f4a5e7442681e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/2b81f8f488044a74b1336e29cb725d7e/wal-000000014 (ops 67-70)
I20260812 06:20:26.957144  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: LogGCOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.034s	user 0.001s	sys 0.029s Metrics: {}
I20260812 06:20:26.957677  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e): perf score=4.173312
I20260812 06:20:26.975631  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.018s	user 0.007s	sys 0.009s Metrics: {"bytes_written":5251342,"delete_count":0,"lbm_write_time_us":7182,"lbm_writes_lt_1ms":131,"reinsert_count":0,"update_count":640}
I20260812 06:20:26.976183  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e): perf score=1.196750
I20260812 06:20:26.985739  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.009s	user 0.004s	sys 0.005s Metrics: {"bytes_written":2953955,"delete_count":0,"lbm_write_time_us":3127,"lbm_writes_lt_1ms":75,"reinsert_count":0,"update_count":360}
I20260812 06:20:26.986223  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling MajorDeltaCompactionOp(2b81f8f488044a74b1336e29cb725d7e): perf score=1.000000
I20260812 06:20:27.171247  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: MajorDeltaCompactionOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.185s	user 0.137s	sys 0.046s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836347,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":552,"lbm_read_time_us":12907,"lbm_reads_lt_1ms":674,"lbm_write_time_us":38286,"lbm_writes_lt_1ms":643,"mutex_wait_us":51,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":12416,"thread_start_us":85,"threads_started":1,"update_count":3000}
I20260812 06:20:27.171897  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e): perf score=14.095187
I20260812 06:20:27.222780  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.051s	user 0.030s	sys 0.020s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20673,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:20:27.223346  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e): perf score=2.188937
I20260812 06:20:27.238191  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.015s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5314,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:27.238791  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling UndoDeltaBlockGCOp(2b81f8f488044a74b1336e29cb725d7e): 483 bytes on disk
I20260812 06:20:27.239216  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: UndoDeltaBlockGCOp(2b81f8f488044a74b1336e29cb725d7e) 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:20:27.239809  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling MajorDeltaCompactionOp(2b81f8f488044a74b1336e29cb725d7e): perf score=1.000000
I20260812 06:20:27.392225  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: MajorDeltaCompactionOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.152s	user 0.120s	sys 0.020s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":702,"lbm_read_time_us":8755,"lbm_reads_lt_1ms":564,"lbm_write_time_us":30456,"lbm_writes_lt_1ms":543,"mutex_wait_us":30,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":55424,"update_count":2500}
I20260812 06:20:27.393940  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e): perf score=14.095187
I20260812 06:20:27.445688  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.052s	user 0.036s	sys 0.008s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19614,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:27.446267  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e): perf score=2.188937
I20260812 06:20:27.458134  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4323,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:27.458834  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling MajorDeltaCompactionOp(2b81f8f488044a74b1336e29cb725d7e): perf score=1.000000
I20260812 06:20:27.612874  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: MajorDeltaCompactionOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.154s	user 0.133s	sys 0.020s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":781,"lbm_read_time_us":10977,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30740,"lbm_writes_lt_1ms":543,"mutex_wait_us":356,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7296,"update_count":2500}
I20260812 06:20:27.613469  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e): perf score=10.126437
I20260812 06:20:27.649096  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.035s	user 0.016s	sys 0.016s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15283,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:27.649677  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e): perf score=2.188937
I20260812 06:20:27.666213  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.016s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6341,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:27.666893  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling MajorDeltaCompactionOp(2b81f8f488044a74b1336e29cb725d7e): perf score=1.000000
I20260812 06:20:27.787202  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: MajorDeltaCompactionOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.120s	user 0.099s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1090,"lbm_read_time_us":8871,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22779,"lbm_writes_lt_1ms":443,"mutex_wait_us":46,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13440,"update_count":2000}
I20260812 06:20:27.787847  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e): perf score=10.126437
I20260812 06:20:27.837365  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.049s	user 0.015s	sys 0.027s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":18361,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:20:27.838299  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e): perf score=2.188937
I20260812 06:20:27.853113  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5439,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:27.853861  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling MajorDeltaCompactionOp(2b81f8f488044a74b1336e29cb725d7e): perf score=1.000000
I20260812 06:20:28.004848  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: MajorDeltaCompactionOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.151s	user 0.095s	sys 0.049s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631314,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":202,"lbm_read_time_us":9154,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25684,"lbm_writes_lt_1ms":443,"mutex_wait_us":41,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8192,"update_count":2000}
I20260812 06:20:28.005604  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e): perf score=11.118625
I20260812 06:20:28.046594  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.041s	user 0.019s	sys 0.020s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16988,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:28.047151  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e): perf score=2.188937
I20260812 06:20:28.070179  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.023s	user 0.007s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4602,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:28.070712  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e): perf score=2.188937
I20260812 06:20:28.081358  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4088,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:28.081857  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling MajorDeltaCompactionOp(2b81f8f488044a74b1336e29cb725d7e): perf score=1.000000
I20260812 06:20:28.247190  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: MajorDeltaCompactionOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.165s	user 0.136s	sys 0.019s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733834,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1319,"lbm_read_time_us":10173,"lbm_reads_lt_1ms":573,"lbm_write_time_us":27298,"lbm_writes_lt_1ms":543,"mutex_wait_us":419,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":2500}
I20260812 06:20:28.247985  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e): perf score=11.118625
I20260812 06:20:28.278568  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.030s	user 0.029s	sys 0.000s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":13235,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:28.279104  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e): perf score=2.188937
I20260812 06:20:28.291569  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4736,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:28.292127  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling FlushMRSOp(2b81f8f488044a74b1336e29cb725d7e): perf score=1.000000
I20260812 06:20:28.320760  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: FlushMRSOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.028s	user 0.027s	sys 0.000s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":102,"dirs.run_cpu_time_us":206,"dirs.run_wall_time_us":1257,"drs_written":1,"lbm_read_time_us":42,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1726,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:20:28.321516  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling LogGCOp(2b81f8f488044a74b1336e29cb725d7e): free 117302581 bytes of WAL
I20260812 06:20:28.321866  1780 log_reader.cc:385] T 2b81f8f488044a74b1336e29cb725d7e: removed 12 log segments from log reader
I20260812 06:20:28.321977  1780 log.cc:1079] T 2b81f8f488044a74b1336e29cb725d7e P 35cb7da96f224476b15f4a5e7442681e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/2b81f8f488044a74b1336e29cb725d7e/wal-000000015 (ops 71-75)
I20260812 06:20:28.322055  1780 log.cc:1079] T 2b81f8f488044a74b1336e29cb725d7e P 35cb7da96f224476b15f4a5e7442681e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/2b81f8f488044a74b1336e29cb725d7e/wal-000000016 (ops 76-80)
I20260812 06:20:28.322118  1780 log.cc:1079] T 2b81f8f488044a74b1336e29cb725d7e P 35cb7da96f224476b15f4a5e7442681e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/2b81f8f488044a74b1336e29cb725d7e/wal-000000017 (ops 81-84)
I20260812 06:20:28.322150  1780 log.cc:1079] T 2b81f8f488044a74b1336e29cb725d7e P 35cb7da96f224476b15f4a5e7442681e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/2b81f8f488044a74b1336e29cb725d7e/wal-000000018 (ops 85-89)
I20260812 06:20:28.322189  1780 log.cc:1079] T 2b81f8f488044a74b1336e29cb725d7e P 35cb7da96f224476b15f4a5e7442681e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/2b81f8f488044a74b1336e29cb725d7e/wal-000000019 (ops 90-94)
I20260812 06:20:28.322227  1780 log.cc:1079] T 2b81f8f488044a74b1336e29cb725d7e P 35cb7da96f224476b15f4a5e7442681e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/2b81f8f488044a74b1336e29cb725d7e/wal-000000020 (ops 95-99)
I20260812 06:20:28.322261  1780 log.cc:1079] T 2b81f8f488044a74b1336e29cb725d7e P 35cb7da96f224476b15f4a5e7442681e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/2b81f8f488044a74b1336e29cb725d7e/wal-000000021 (ops 100-104)
I20260812 06:20:28.322300  1780 log.cc:1079] T 2b81f8f488044a74b1336e29cb725d7e P 35cb7da96f224476b15f4a5e7442681e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/2b81f8f488044a74b1336e29cb725d7e/wal-000000022 (ops 105-108)
I20260812 06:20:28.322338  1780 log.cc:1079] T 2b81f8f488044a74b1336e29cb725d7e P 35cb7da96f224476b15f4a5e7442681e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/2b81f8f488044a74b1336e29cb725d7e/wal-000000023 (ops 109-113)
I20260812 06:20:28.322376  1780 log.cc:1079] T 2b81f8f488044a74b1336e29cb725d7e P 35cb7da96f224476b15f4a5e7442681e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/2b81f8f488044a74b1336e29cb725d7e/wal-000000024 (ops 114-118)
I20260812 06:20:28.322412  1780 log.cc:1079] T 2b81f8f488044a74b1336e29cb725d7e P 35cb7da96f224476b15f4a5e7442681e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/2b81f8f488044a74b1336e29cb725d7e/wal-000000025 (ops 119-123)
I20260812 06:20:28.322448  1780 log.cc:1079] T 2b81f8f488044a74b1336e29cb725d7e P 35cb7da96f224476b15f4a5e7442681e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/2b81f8f488044a74b1336e29cb725d7e/wal-000000026 (ops 124-128)
I20260812 06:20:28.350602  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: LogGCOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.029s	user 0.000s	sys 0.028s Metrics: {}
I20260812 06:20:28.351293  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e): perf score=3.181125
I20260812 06:20:28.366811  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.015s	user 0.009s	sys 0.005s Metrics: {"bytes_written":5128262,"delete_count":0,"lbm_write_time_us":5912,"lbm_writes_lt_1ms":128,"reinsert_count":0,"update_count":625}
I20260812 06:20:28.367368  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling UndoDeltaBlockGCOp(2b81f8f488044a74b1336e29cb725d7e): 462 bytes on disk
I20260812 06:20:28.367846  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: UndoDeltaBlockGCOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4}
I20260812 06:20:28.368372  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e): perf score=1.196750
I20260812 06:20:28.378098  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3077030,"delete_count":0,"lbm_write_time_us":3047,"lbm_writes_lt_1ms":78,"reinsert_count":0,"update_count":375}
I20260812 06:20:28.378736  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling MajorDeltaCompactionOp(2b81f8f488044a74b1336e29cb725d7e): perf score=1.000000
I20260812 06:20:28.590358  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: MajorDeltaCompactionOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.211s	user 0.165s	sys 0.040s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836340,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1494,"lbm_read_time_us":12604,"lbm_reads_lt_1ms":674,"lbm_write_time_us":34654,"lbm_writes_lt_1ms":643,"mutex_wait_us":28,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":12544,"thread_start_us":97,"threads_started":1,"update_count":3000}
I20260812 06:20:28.591080  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e): perf score=14.095187
I20260812 06:20:28.637353  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.046s	user 0.029s	sys 0.012s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20738,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:20:28.638019  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e): perf score=2.188937
I20260812 06:20:28.662169  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.024s	user 0.012s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5343,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:28.662813  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling MajorDeltaCompactionOp(2b81f8f488044a74b1336e29cb725d7e): perf score=1.000000
I20260812 06:20:28.849885  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: MajorDeltaCompactionOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.187s	user 0.115s	sys 0.069s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":751,"lbm_read_time_us":10049,"lbm_reads_lt_1ms":564,"lbm_write_time_us":31819,"lbm_writes_lt_1ms":543,"mutex_wait_us":43,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14080,"update_count":2500}
I20260812 06:20:28.850878  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e): perf score=14.095187
I20260812 06:20:28.893837  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.043s	user 0.022s	sys 0.020s Metrics: {"bytes_written":16409911,"delete_count":0,"lbm_write_time_us":19327,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:28.894407  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e): perf score=2.188937
I20260812 06:20:28.907089  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.012s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4670,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:28.907819  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling MajorDeltaCompactionOp(2b81f8f488044a74b1336e29cb725d7e): perf score=1.000000
I20260812 06:20:29.091825  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: MajorDeltaCompactionOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.184s	user 0.116s	sys 0.064s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733732,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1240,"lbm_read_time_us":11080,"lbm_reads_lt_1ms":564,"lbm_write_time_us":31982,"lbm_writes_lt_1ms":543,"mutex_wait_us":362,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":16000,"update_count":2500}
I20260812 06:20:29.092531  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e): perf score=14.095187
I20260812 06:20:29.144861  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.052s	user 0.021s	sys 0.028s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22950,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:29.145444  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e): perf score=2.188937
I20260812 06:20:29.161775  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.016s	user 0.007s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6391,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:29.162354  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling MajorDeltaCompactionOp(2b81f8f488044a74b1336e29cb725d7e): perf score=1.000000
I20260812 06:20:29.317839  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: MajorDeltaCompactionOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.155s	user 0.116s	sys 0.037s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":300,"lbm_read_time_us":10667,"lbm_reads_lt_1ms":564,"lbm_write_time_us":32678,"lbm_writes_lt_1ms":543,"mutex_wait_us":84,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3712,"update_count":2500}
I20260812 06:20:29.318990  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e): perf score=11.118625
I20260812 06:20:29.354328  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.035s	user 0.014s	sys 0.020s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15015,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:29.354897  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e): perf score=2.188937
I20260812 06:20:29.380228  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.025s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5578,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:29.380878  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e): perf score=2.188937
I20260812 06:20:29.391863  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4103,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:29.393046  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling MajorDeltaCompactionOp(2b81f8f488044a74b1336e29cb725d7e): perf score=1.000000
I20260812 06:20:29.557651  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: MajorDeltaCompactionOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.164s	user 0.119s	sys 0.040s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733834,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":325,"lbm_read_time_us":11533,"lbm_reads_lt_1ms":573,"lbm_write_time_us":32371,"lbm_writes_lt_1ms":543,"mutex_wait_us":60,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6144,"update_count":2500}
I20260812 06:20:29.558368  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e): perf score=11.118625
I20260812 06:20:29.598649  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.040s	user 0.027s	sys 0.012s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":17532,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:29.599241  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e): perf score=2.188937
I20260812 06:20:29.612437  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.013s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3737,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:29.613010  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling MajorDeltaCompactionOp(2b81f8f488044a74b1336e29cb725d7e): perf score=1.000000
I20260812 06:20:29.740283  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: MajorDeltaCompactionOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.127s	user 0.098s	sys 0.027s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631302,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1072,"lbm_read_time_us":7378,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26040,"lbm_writes_lt_1ms":443,"mutex_wait_us":315,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:20:29.741233  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e): perf score=11.118625
I20260812 06:20:29.793895  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.052s	user 0.027s	sys 0.024s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":27555,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":310,"reinsert_count":0,"update_count":1550}
I20260812 06:20:29.794459  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e): perf score=2.188937
I20260812 06:20:29.815382  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.021s	user 0.004s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5309,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:29.815927  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e): perf score=2.188937
I20260812 06:20:29.827013  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4334,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:29.827530  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling FlushMRSOp(2b81f8f488044a74b1336e29cb725d7e): perf score=1.000000
I20260812 06:20:29.861147  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: FlushMRSOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.033s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":101,"dirs.run_cpu_time_us":252,"dirs.run_wall_time_us":1351,"drs_written":1,"lbm_read_time_us":46,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1956,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:20:29.862010  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling LogGCOp(2b81f8f488044a74b1336e29cb725d7e): free 132571539 bytes of WAL
I20260812 06:20:29.862272  1780 log_reader.cc:385] T 2b81f8f488044a74b1336e29cb725d7e: removed 13 log segments from log reader
I20260812 06:20:29.862344  1780 log.cc:1079] T 2b81f8f488044a74b1336e29cb725d7e P 35cb7da96f224476b15f4a5e7442681e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/2b81f8f488044a74b1336e29cb725d7e/wal-000000027 (ops 129-132)
I20260812 06:20:29.862396  1780 log.cc:1079] T 2b81f8f488044a74b1336e29cb725d7e P 35cb7da96f224476b15f4a5e7442681e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/2b81f8f488044a74b1336e29cb725d7e/wal-000000028 (ops 133-137)
I20260812 06:20:29.862453  1780 log.cc:1079] T 2b81f8f488044a74b1336e29cb725d7e P 35cb7da96f224476b15f4a5e7442681e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/2b81f8f488044a74b1336e29cb725d7e/wal-000000029 (ops 138-142)
I20260812 06:20:29.862496  1780 log.cc:1079] T 2b81f8f488044a74b1336e29cb725d7e P 35cb7da96f224476b15f4a5e7442681e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/2b81f8f488044a74b1336e29cb725d7e/wal-000000030 (ops 143-147)
I20260812 06:20:29.862537  1780 log.cc:1079] T 2b81f8f488044a74b1336e29cb725d7e P 35cb7da96f224476b15f4a5e7442681e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/2b81f8f488044a74b1336e29cb725d7e/wal-000000031 (ops 148-152)
I20260812 06:20:29.862586  1780 log.cc:1079] T 2b81f8f488044a74b1336e29cb725d7e P 35cb7da96f224476b15f4a5e7442681e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/2b81f8f488044a74b1336e29cb725d7e/wal-000000032 (ops 153-157)
I20260812 06:20:29.862627  1780 log.cc:1079] T 2b81f8f488044a74b1336e29cb725d7e P 35cb7da96f224476b15f4a5e7442681e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/2b81f8f488044a74b1336e29cb725d7e/wal-000000033 (ops 158-162)
I20260812 06:20:29.862664  1780 log.cc:1079] T 2b81f8f488044a74b1336e29cb725d7e P 35cb7da96f224476b15f4a5e7442681e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/2b81f8f488044a74b1336e29cb725d7e/wal-000000034 (ops 163-167)
I20260812 06:20:29.862704  1780 log.cc:1079] T 2b81f8f488044a74b1336e29cb725d7e P 35cb7da96f224476b15f4a5e7442681e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/2b81f8f488044a74b1336e29cb725d7e/wal-000000035 (ops 168-172)
I20260812 06:20:29.862744  1780 log.cc:1079] T 2b81f8f488044a74b1336e29cb725d7e P 35cb7da96f224476b15f4a5e7442681e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/2b81f8f488044a74b1336e29cb725d7e/wal-000000036 (ops 173-176)
I20260812 06:20:29.862784  1780 log.cc:1079] T 2b81f8f488044a74b1336e29cb725d7e P 35cb7da96f224476b15f4a5e7442681e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/2b81f8f488044a74b1336e29cb725d7e/wal-000000037 (ops 177-181)
I20260812 06:20:29.862824  1780 log.cc:1079] T 2b81f8f488044a74b1336e29cb725d7e P 35cb7da96f224476b15f4a5e7442681e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/2b81f8f488044a74b1336e29cb725d7e/wal-000000038 (ops 182-186)
I20260812 06:20:29.862864  1780 log.cc:1079] T 2b81f8f488044a74b1336e29cb725d7e P 35cb7da96f224476b15f4a5e7442681e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/2b81f8f488044a74b1336e29cb725d7e/wal-000000039 (ops 187-191)
I20260812 06:20:29.892379  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: LogGCOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.030s	user 0.004s	sys 0.024s Metrics: {}
I20260812 06:20:29.892987  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling UndoDeltaBlockGCOp(2b81f8f488044a74b1336e29cb725d7e): 482 bytes on disk
I20260812 06:20:29.893649  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: UndoDeltaBlockGCOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":77,"lbm_reads_lt_1ms":4}
I20260812 06:20:29.894519  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e): perf score=5.165500
I20260812 06:20:29.914346  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.020s	user 0.019s	sys 0.000s Metrics: {"bytes_written":7425617,"delete_count":0,"lbm_write_time_us":7864,"lbm_writes_lt_1ms":184,"reinsert_count":0,"update_count":905}
I20260812 06:20:29.914896  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling MajorDeltaCompactionOp(2b81f8f488044a74b1336e29cb725d7e): perf score=1.000000
I20260812 06:20:30.117337  1664 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.953s	user 1.860s	sys 0.064s
I20260812 06:20:30.141355  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: MajorDeltaCompactionOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.226s	user 0.152s	sys 0.071s Metrics: {"cfile_cache_miss":715,"cfile_cache_miss_bytes":32159317,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":16554,"lbm_reads_lt_1ms":747,"lbm_write_time_us":43786,"lbm_writes_lt_1ms":724,"peak_mem_usage":85108611,"reinsert_count":0,"spinlock_wait_cycles":3456,"update_count":3405}
I20260812 06:20:30.141987  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e): perf score=15.087375
I20260812 06:20:30.191416  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: FlushDeltaMemStoresOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.049s	user 0.036s	sys 0.013s Metrics: {"bytes_written":17189364,"delete_count":0,"lbm_write_time_us":23018,"lbm_writes_lt_1ms":422,"reinsert_count":0,"spinlock_wait_cycles":4480,"update_count":2095}
I20260812 06:20:30.191890  1849 maintenance_manager.cc:419] P 35cb7da96f224476b15f4a5e7442681e: Scheduling MajorDeltaCompactionOp(2b81f8f488044a74b1336e29cb725d7e): perf score=1.000000
I20260812 06:20:30.212723  1664 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.095s	user 0.001s	sys 0.000s
I20260812 06:20:30.213428  1664 tablet_server.cc:179] TabletServer@127.1.160.1:0 shutting down...
I20260812 06:20:30.305382  1780 maintenance_manager.cc:643] P 35cb7da96f224476b15f4a5e7442681e: MajorDeltaCompactionOp(2b81f8f488044a74b1336e29cb725d7e) complete. Timing: real 0.113s	user 0.084s	sys 0.028s Metrics: {"cfile_cache_miss":450,"cfile_cache_miss_bytes":21410655,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":624,"lbm_read_time_us":9299,"lbm_reads_lt_1ms":486,"lbm_write_time_us":22318,"lbm_writes_lt_1ms":462,"mutex_wait_us":140,"peak_mem_usage":52509377,"reinsert_count":0,"spinlock_wait_cycles":15104,"update_count":2095}
I20260812 06:20:30.306265  1664 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:20:30.306663  1664 tablet_replica.cc:333] T 2b81f8f488044a74b1336e29cb725d7e P 35cb7da96f224476b15f4a5e7442681e: stopping tablet replica
I20260812 06:20:30.306912  1664 raft_consensus.cc:2243] T 2b81f8f488044a74b1336e29cb725d7e P 35cb7da96f224476b15f4a5e7442681e [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:30.307163  1664 raft_consensus.cc:2272] T 2b81f8f488044a74b1336e29cb725d7e P 35cb7da96f224476b15f4a5e7442681e [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:30.323021  1664 tablet_server.cc:196] TabletServer@127.1.160.1:0 shutdown complete.
I20260812 06:20:30.347702  1664 master.cc:562] Master@127.1.160.62:38203 shutting down...
I20260812 06:20:30.351403  1664 raft_consensus.cc:2243] T 00000000000000000000000000000000 P b7e839a726a34191a4d5d8858137a351 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:30.351620  1664 raft_consensus.cc:2272] T 00000000000000000000000000000000 P b7e839a726a34191a4d5d8858137a351 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:30.351719  1664 tablet_replica.cc:333] T 00000000000000000000000000000000 P b7e839a726a34191a4d5d8858137a351: stopping tablet replica
I20260812 06:20:30.364125  1664 master.cc:584] Master@127.1.160.62:38203 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5581 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:20:30.465183  1664 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.1.160.62:38245
I20260812 06:20:30.465714  1664 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:30.468253  1883 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:20:30.468333  1886 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:20:30.468350  1884 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:20:30.468276  1664 server_base.cc:1061] running on GCE node
I20260812 06:20:30.468670  1664 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:30.468734  1664 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:20:30.468770  1664 hybrid_clock.cc:648] HybridClock initialized: now 1786515630468768 us; error 0 us; skew 500 ppm
I20260812 06:20:30.469767  1664 webserver.cc:533] Webserver started at http://127.1.160.62:38085/ using document root <none> and password file <none>
I20260812 06:20:30.469959  1664 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:30.470009  1664 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:30.470082  1664 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:30.470528  1664 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624860936-1664-0/minicluster-data/master-0-root/instance:
uuid: "8d005205855a4c589a4ca84db45bdf52"
format_stamp: "Formatted at 2026-08-12 06:20:30 on dist-test-slave-njxd"
I20260812 06:20:30.472082  1664 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:20:30.473023  1893 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:20:30.473255  1664 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:20:30.473349  1664 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624860936-1664-0/minicluster-data/master-0-root
uuid: "8d005205855a4c589a4ca84db45bdf52"
format_stamp: "Formatted at 2026-08-12 06:20:30 on dist-test-slave-njxd"
I20260812 06:20:30.473438  1664 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624860936-1664-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624860936-1664-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624860936-1664-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:20:30.496058  1664 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:30.496506  1664 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:30.501315  1664 rpc_server.cc:307] RPC server started. Bound to: 127.1.160.62:38245
I20260812 06:20:30.506271  1955 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.1.160.62:38245 every 8 connection(s)
I20260812 06:20:30.506541  1956 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:20:30.508579  1956 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 8d005205855a4c589a4ca84db45bdf52: Bootstrap starting.
I20260812 06:20:30.509449  1956 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 8d005205855a4c589a4ca84db45bdf52: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:30.510586  1956 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 8d005205855a4c589a4ca84db45bdf52: No bootstrap required, opened a new log
I20260812 06:20:30.511041  1956 raft_consensus.cc:359] T 00000000000000000000000000000000 P 8d005205855a4c589a4ca84db45bdf52 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8d005205855a4c589a4ca84db45bdf52" member_type: VOTER }
I20260812 06:20:30.511132  1956 raft_consensus.cc:385] T 00000000000000000000000000000000 P 8d005205855a4c589a4ca84db45bdf52 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:30.511155  1956 raft_consensus.cc:740] T 00000000000000000000000000000000 P 8d005205855a4c589a4ca84db45bdf52 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 8d005205855a4c589a4ca84db45bdf52, State: Initialized, Role: FOLLOWER
I20260812 06:20:30.511364  1956 consensus_queue.cc:260] T 00000000000000000000000000000000 P 8d005205855a4c589a4ca84db45bdf52 [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: "8d005205855a4c589a4ca84db45bdf52" member_type: VOTER }
I20260812 06:20:30.511442  1956 raft_consensus.cc:399] T 00000000000000000000000000000000 P 8d005205855a4c589a4ca84db45bdf52 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:30.511488  1956 raft_consensus.cc:493] T 00000000000000000000000000000000 P 8d005205855a4c589a4ca84db45bdf52 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:30.511550  1956 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 8d005205855a4c589a4ca84db45bdf52 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:30.512326  1956 raft_consensus.cc:515] T 00000000000000000000000000000000 P 8d005205855a4c589a4ca84db45bdf52 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8d005205855a4c589a4ca84db45bdf52" member_type: VOTER }
I20260812 06:20:30.512480  1956 leader_election.cc:304] T 00000000000000000000000000000000 P 8d005205855a4c589a4ca84db45bdf52 [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: 8d005205855a4c589a4ca84db45bdf52; no voters: 
I20260812 06:20:30.512718  1956 leader_election.cc:290] T 00000000000000000000000000000000 P 8d005205855a4c589a4ca84db45bdf52 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:30.512867  1960 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 8d005205855a4c589a4ca84db45bdf52 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:30.513110  1960 raft_consensus.cc:697] T 00000000000000000000000000000000 P 8d005205855a4c589a4ca84db45bdf52 [term 1 LEADER]: Becoming Leader. State: Replica: 8d005205855a4c589a4ca84db45bdf52, State: Running, Role: LEADER
I20260812 06:20:30.513259  1956 sys_catalog.cc:565] T 00000000000000000000000000000000 P 8d005205855a4c589a4ca84db45bdf52 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:20:30.513270  1960 consensus_queue.cc:237] T 00000000000000000000000000000000 P 8d005205855a4c589a4ca84db45bdf52 [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: "8d005205855a4c589a4ca84db45bdf52" member_type: VOTER }
I20260812 06:20:30.513865  1961 sys_catalog.cc:455] T 00000000000000000000000000000000 P 8d005205855a4c589a4ca84db45bdf52 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "8d005205855a4c589a4ca84db45bdf52" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8d005205855a4c589a4ca84db45bdf52" member_type: VOTER } }
I20260812 06:20:30.513995  1961 sys_catalog.cc:458] T 00000000000000000000000000000000 P 8d005205855a4c589a4ca84db45bdf52 [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:30.513870  1962 sys_catalog.cc:455] T 00000000000000000000000000000000 P 8d005205855a4c589a4ca84db45bdf52 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 8d005205855a4c589a4ca84db45bdf52. Latest consensus state: current_term: 1 leader_uuid: "8d005205855a4c589a4ca84db45bdf52" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8d005205855a4c589a4ca84db45bdf52" member_type: VOTER } }
I20260812 06:20:30.514144  1962 sys_catalog.cc:458] T 00000000000000000000000000000000 P 8d005205855a4c589a4ca84db45bdf52 [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:30.514695  1966 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:20:30.515416  1966 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:20:30.515605  1664 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:20:30.517264  1966 catalog_manager.cc:1383] Generated new cluster ID: fe78329ffd8944e4848d4418dfb12e70
I20260812 06:20:30.517323  1966 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:20:30.536478  1966 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:20:30.537096  1966 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:20:30.548681  1966 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 8d005205855a4c589a4ca84db45bdf52: Generated new TSK 0
I20260812 06:20:30.548918  1966 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:20:30.580408  1664 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:30.582542  1987 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:20:30.582710  1984 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:20:30.582520  1983 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:20:30.582716  1664 server_base.cc:1061] running on GCE node
I20260812 06:20:30.583082  1664 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:30.583161  1664 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:20:30.583189  1664 hybrid_clock.cc:648] HybridClock initialized: now 1786515630583188 us; error 0 us; skew 500 ppm
I20260812 06:20:30.584075  1664 webserver.cc:533] Webserver started at http://127.1.160.1:38835/ using document root <none> and password file <none>
I20260812 06:20:30.584287  1664 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:30.584364  1664 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:30.584451  1664 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:30.584884  1664 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624860936-1664-0/minicluster-data/ts-0-root/instance:
uuid: "47dba07a335b4b10a16b3ac1330e002e"
format_stamp: "Formatted at 2026-08-12 06:20:30 on dist-test-slave-njxd"
I20260812 06:20:30.586531  1664 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:20:30.587496  1993 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:20:30.587791  1664 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:20:30.587883  1664 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624860936-1664-0/minicluster-data/ts-0-root
uuid: "47dba07a335b4b10a16b3ac1330e002e"
format_stamp: "Formatted at 2026-08-12 06:20:30 on dist-test-slave-njxd"
I20260812 06:20:30.587972  1664 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624860936-1664-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624860936-1664-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624860936-1664-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:20:30.597371  1664 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:30.597858  1664 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:30.598197  1664 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:20:30.598670  1664 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:20:30.598730  1664 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:30.598793  1664 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:20:30.598829  1664 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:30.603281  1664 rpc_server.cc:307] RPC server started. Bound to: 127.1.160.1:44531
I20260812 06:20:30.605261  2070 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.1.160.1:44531 every 8 connection(s)
I20260812 06:20:30.613165  2071 heartbeater.cc:344] Connected to a master server at 127.1.160.62:38245
I20260812 06:20:30.613336  2071 heartbeater.cc:461] Registering TS with master...
I20260812 06:20:30.613684  2071 heartbeater.cc:507] Master 127.1.160.62:38245 requested a full tablet report, sending...
I20260812 06:20:30.614464  1914 ts_manager.cc:194] Registered new tserver with Master: 47dba07a335b4b10a16b3ac1330e002e (127.1.160.1:44531)
I20260812 06:20:30.615202  1664 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011100771s
I20260812 06:20:30.615401  1914 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:39964
I20260812 06:20:30.622605  1914 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:39970:
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:20:30.631687  2028 tablet_service.cc:1511] Processing CreateTablet for tablet f064407d0a5a4f269998a203ab407842 (DEFAULT_TABLE table=heavy-update-compaction-test [id=b23851172198461a860ce5bbd12d6d9e]), partition=
I20260812 06:20:30.632006  2028 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet f064407d0a5a4f269998a203ab407842. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:20:30.634172  2083 tablet_bootstrap.cc:492] T f064407d0a5a4f269998a203ab407842 P 47dba07a335b4b10a16b3ac1330e002e: Bootstrap starting.
I20260812 06:20:30.635064  2083 tablet_bootstrap.cc:654] T f064407d0a5a4f269998a203ab407842 P 47dba07a335b4b10a16b3ac1330e002e: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:30.636219  2083 tablet_bootstrap.cc:492] T f064407d0a5a4f269998a203ab407842 P 47dba07a335b4b10a16b3ac1330e002e: No bootstrap required, opened a new log
I20260812 06:20:30.636337  2083 ts_tablet_manager.cc:1403] T f064407d0a5a4f269998a203ab407842 P 47dba07a335b4b10a16b3ac1330e002e: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:20:30.636885  2083 raft_consensus.cc:359] T f064407d0a5a4f269998a203ab407842 P 47dba07a335b4b10a16b3ac1330e002e [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "47dba07a335b4b10a16b3ac1330e002e" member_type: VOTER last_known_addr { host: "127.1.160.1" port: 44531 } }
I20260812 06:20:30.637004  2083 raft_consensus.cc:385] T f064407d0a5a4f269998a203ab407842 P 47dba07a335b4b10a16b3ac1330e002e [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:30.637053  2083 raft_consensus.cc:740] T f064407d0a5a4f269998a203ab407842 P 47dba07a335b4b10a16b3ac1330e002e [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 47dba07a335b4b10a16b3ac1330e002e, State: Initialized, Role: FOLLOWER
I20260812 06:20:30.637200  2083 consensus_queue.cc:260] T f064407d0a5a4f269998a203ab407842 P 47dba07a335b4b10a16b3ac1330e002e [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: "47dba07a335b4b10a16b3ac1330e002e" member_type: VOTER last_known_addr { host: "127.1.160.1" port: 44531 } }
I20260812 06:20:30.637336  2083 raft_consensus.cc:399] T f064407d0a5a4f269998a203ab407842 P 47dba07a335b4b10a16b3ac1330e002e [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:30.637389  2083 raft_consensus.cc:493] T f064407d0a5a4f269998a203ab407842 P 47dba07a335b4b10a16b3ac1330e002e [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:30.637452  2083 raft_consensus.cc:3060] T f064407d0a5a4f269998a203ab407842 P 47dba07a335b4b10a16b3ac1330e002e [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:30.638381  2083 raft_consensus.cc:515] T f064407d0a5a4f269998a203ab407842 P 47dba07a335b4b10a16b3ac1330e002e [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "47dba07a335b4b10a16b3ac1330e002e" member_type: VOTER last_known_addr { host: "127.1.160.1" port: 44531 } }
I20260812 06:20:30.638549  2083 leader_election.cc:304] T f064407d0a5a4f269998a203ab407842 P 47dba07a335b4b10a16b3ac1330e002e [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: 47dba07a335b4b10a16b3ac1330e002e; no voters: 
I20260812 06:20:30.638808  2083 leader_election.cc:290] T f064407d0a5a4f269998a203ab407842 P 47dba07a335b4b10a16b3ac1330e002e [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:30.638960  2085 raft_consensus.cc:2804] T f064407d0a5a4f269998a203ab407842 P 47dba07a335b4b10a16b3ac1330e002e [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:30.639287  2071 heartbeater.cc:499] Master 127.1.160.62:38245 was elected leader, sending a full tablet report...
I20260812 06:20:30.639317  2085 raft_consensus.cc:697] T f064407d0a5a4f269998a203ab407842 P 47dba07a335b4b10a16b3ac1330e002e [term 1 LEADER]: Becoming Leader. State: Replica: 47dba07a335b4b10a16b3ac1330e002e, State: Running, Role: LEADER
I20260812 06:20:30.639372  2083 ts_tablet_manager.cc:1434] T f064407d0a5a4f269998a203ab407842 P 47dba07a335b4b10a16b3ac1330e002e: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:20:30.639447  2085 consensus_queue.cc:237] T f064407d0a5a4f269998a203ab407842 P 47dba07a335b4b10a16b3ac1330e002e [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: "47dba07a335b4b10a16b3ac1330e002e" member_type: VOTER last_known_addr { host: "127.1.160.1" port: 44531 } }
I20260812 06:20:30.640870  1914 catalog_manager.cc:5719] T f064407d0a5a4f269998a203ab407842 P 47dba07a335b4b10a16b3ac1330e002e reported cstate change: term changed from 0 to 1, leader changed from <none> to 47dba07a335b4b10a16b3ac1330e002e (127.1.160.1). New cstate: current_term: 1 leader_uuid: "47dba07a335b4b10a16b3ac1330e002e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "47dba07a335b4b10a16b3ac1330e002e" member_type: VOTER last_known_addr { host: "127.1.160.1" port: 44531 } health_report { overall_health: HEALTHY } } }
I20260812 06:20:30.702190  1664 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.055s	user 0.013s	sys 0.010s
I20260812 06:20:30.855850  2072 maintenance_manager.cc:419] P 47dba07a335b4b10a16b3ac1330e002e: Scheduling FlushMRSOp(f064407d0a5a4f269998a203ab407842): perf score=19.054940
I20260812 06:20:31.024577  1999 maintenance_manager.cc:643] P 47dba07a335b4b10a16b3ac1330e002e: FlushMRSOp(f064407d0a5a4f269998a203ab407842) complete. Timing: real 0.168s	user 0.130s	sys 0.035s Metrics: {"bytes_written":12307489,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":77,"dirs.run_cpu_time_us":179,"dirs.run_wall_time_us":1168,"drs_written":1,"lbm_read_time_us":86,"lbm_reads_lt_1ms":4,"lbm_write_time_us":41611,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:20:31.025318  2072 maintenance_manager.cc:419] P 47dba07a335b4b10a16b3ac1330e002e: Scheduling LogGCOp(f064407d0a5a4f269998a203ab407842): free 20743880 bytes of WAL
I20260812 06:20:31.025605  1999 log_reader.cc:385] T f064407d0a5a4f269998a203ab407842: removed 2 log segments from log reader
I20260812 06:20:31.025681  1999 log.cc:1079] T f064407d0a5a4f269998a203ab407842 P 47dba07a335b4b10a16b3ac1330e002e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/f064407d0a5a4f269998a203ab407842/wal-000000001 (ops 1-6)
I20260812 06:20:31.025730  1999 log.cc:1079] T f064407d0a5a4f269998a203ab407842 P 47dba07a335b4b10a16b3ac1330e002e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/f064407d0a5a4f269998a203ab407842/wal-000000002 (ops 7-11)
I20260812 06:20:31.031917  1999 maintenance_manager.cc:643] P 47dba07a335b4b10a16b3ac1330e002e: LogGCOp(f064407d0a5a4f269998a203ab407842) complete. Timing: real 0.006s	user 0.001s	sys 0.003s Metrics: {}
I20260812 06:20:31.032397  2072 maintenance_manager.cc:419] P 47dba07a335b4b10a16b3ac1330e002e: Scheduling UndoDeltaBlockGCOp(f064407d0a5a4f269998a203ab407842): 16411393 bytes on disk
I20260812 06:20:31.033002  1999 maintenance_manager.cc:643] P 47dba07a335b4b10a16b3ac1330e002e: UndoDeltaBlockGCOp(f064407d0a5a4f269998a203ab407842) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":115,"lbm_reads_lt_1ms":4}
I20260812 06:20:31.033557  2072 maintenance_manager.cc:419] P 47dba07a335b4b10a16b3ac1330e002e: Scheduling FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842): perf score=2.188937
I20260812 06:20:31.049906  1999 maintenance_manager.cc:643] P 47dba07a335b4b10a16b3ac1330e002e: FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842) complete. Timing: real 0.016s	user 0.003s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4573,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:31.050370  2072 maintenance_manager.cc:419] P 47dba07a335b4b10a16b3ac1330e002e: Scheduling MajorDeltaCompactionOp(f064407d0a5a4f269998a203ab407842): perf score=1.000000
I20260812 06:20:31.212942  1999 maintenance_manager.cc:643] P 47dba07a335b4b10a16b3ac1330e002e: MajorDeltaCompactionOp(f064407d0a5a4f269998a203ab407842) complete. Timing: real 0.162s	user 0.110s	sys 0.052s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":619,"lbm_read_time_us":11311,"lbm_reads_lt_1ms":460,"lbm_write_time_us":25278,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5760,"thread_start_us":367,"threads_started":5,"update_count":2000}
I20260812 06:20:31.213528  2072 maintenance_manager.cc:419] P 47dba07a335b4b10a16b3ac1330e002e: Scheduling FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842): perf score=14.095187
I20260812 06:20:31.263361  1999 maintenance_manager.cc:643] P 47dba07a335b4b10a16b3ac1330e002e: FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842) complete. Timing: real 0.050s	user 0.011s	sys 0.037s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22585,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:31.263839  2072 maintenance_manager.cc:419] P 47dba07a335b4b10a16b3ac1330e002e: Scheduling FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842): perf score=2.188937
I20260812 06:20:31.284749  1999 maintenance_manager.cc:643] P 47dba07a335b4b10a16b3ac1330e002e: FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842) complete. Timing: real 0.021s	user 0.010s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4145,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:31.285452  2072 maintenance_manager.cc:419] P 47dba07a335b4b10a16b3ac1330e002e: Scheduling MajorDeltaCompactionOp(f064407d0a5a4f269998a203ab407842): perf score=1.000000
I20260812 06:20:31.483836  1999 maintenance_manager.cc:643] P 47dba07a335b4b10a16b3ac1330e002e: MajorDeltaCompactionOp(f064407d0a5a4f269998a203ab407842) complete. Timing: real 0.198s	user 0.132s	sys 0.057s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":742,"lbm_read_time_us":12829,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30996,"lbm_writes_lt_1ms":543,"mutex_wait_us":325,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2500}
I20260812 06:20:31.484403  2072 maintenance_manager.cc:419] P 47dba07a335b4b10a16b3ac1330e002e: Scheduling FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842): perf score=14.095187
I20260812 06:20:31.539711  1999 maintenance_manager.cc:643] P 47dba07a335b4b10a16b3ac1330e002e: FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842) complete. Timing: real 0.055s	user 0.027s	sys 0.016s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":19759,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:31.540222  2072 maintenance_manager.cc:419] P 47dba07a335b4b10a16b3ac1330e002e: Scheduling FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842): perf score=2.188937
I20260812 06:20:31.552553  1999 maintenance_manager.cc:643] P 47dba07a335b4b10a16b3ac1330e002e: FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842) complete. Timing: real 0.012s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4036,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:31.553061  2072 maintenance_manager.cc:419] P 47dba07a335b4b10a16b3ac1330e002e: Scheduling MajorDeltaCompactionOp(f064407d0a5a4f269998a203ab407842): perf score=1.000000
I20260812 06:20:31.751339  1999 maintenance_manager.cc:643] P 47dba07a335b4b10a16b3ac1330e002e: MajorDeltaCompactionOp(f064407d0a5a4f269998a203ab407842) complete. Timing: real 0.198s	user 0.119s	sys 0.068s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":877,"lbm_read_time_us":12561,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32643,"lbm_writes_lt_1ms":543,"mutex_wait_us":21,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":15232,"update_count":2500}
I20260812 06:20:31.752055  2072 maintenance_manager.cc:419] P 47dba07a335b4b10a16b3ac1330e002e: Scheduling FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842): perf score=14.095187
I20260812 06:20:31.800664  1999 maintenance_manager.cc:643] P 47dba07a335b4b10a16b3ac1330e002e: FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842) complete. Timing: real 0.048s	user 0.027s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19546,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:31.801344  2072 maintenance_manager.cc:419] P 47dba07a335b4b10a16b3ac1330e002e: Scheduling FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842): perf score=2.188937
I20260812 06:20:31.813956  1999 maintenance_manager.cc:643] P 47dba07a335b4b10a16b3ac1330e002e: FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842) complete. Timing: real 0.012s	user 0.009s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4419,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:31.814393  2072 maintenance_manager.cc:419] P 47dba07a335b4b10a16b3ac1330e002e: Scheduling MajorDeltaCompactionOp(f064407d0a5a4f269998a203ab407842): perf score=1.000000
I20260812 06:20:31.970840  1999 maintenance_manager.cc:643] P 47dba07a335b4b10a16b3ac1330e002e: MajorDeltaCompactionOp(f064407d0a5a4f269998a203ab407842) complete. Timing: real 0.156s	user 0.078s	sys 0.067s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":161,"lbm_read_time_us":10037,"lbm_reads_lt_1ms":564,"lbm_write_time_us":31339,"lbm_writes_lt_1ms":543,"mutex_wait_us":21,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11776,"update_count":2500}
I20260812 06:20:31.971544  2072 maintenance_manager.cc:419] P 47dba07a335b4b10a16b3ac1330e002e: Scheduling FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842): perf score=14.095187
I20260812 06:20:32.027697  1999 maintenance_manager.cc:643] P 47dba07a335b4b10a16b3ac1330e002e: FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842) complete. Timing: real 0.056s	user 0.032s	sys 0.012s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":21287,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:32.028331  2072 maintenance_manager.cc:419] P 47dba07a335b4b10a16b3ac1330e002e: Scheduling FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842): perf score=2.188937
I20260812 06:20:32.040158  1999 maintenance_manager.cc:643] P 47dba07a335b4b10a16b3ac1330e002e: FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842) complete. Timing: real 0.012s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4079,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:32.040675  2072 maintenance_manager.cc:419] P 47dba07a335b4b10a16b3ac1330e002e: Scheduling MajorDeltaCompactionOp(f064407d0a5a4f269998a203ab407842): perf score=1.000000
I20260812 06:20:32.200479  1999 maintenance_manager.cc:643] P 47dba07a335b4b10a16b3ac1330e002e: MajorDeltaCompactionOp(f064407d0a5a4f269998a203ab407842) complete. Timing: real 0.160s	user 0.142s	sys 0.012s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":881,"lbm_read_time_us":10656,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32649,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":16768,"update_count":2500}
I20260812 06:20:32.201135  2072 maintenance_manager.cc:419] P 47dba07a335b4b10a16b3ac1330e002e: Scheduling FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842): perf score=14.095187
I20260812 06:20:32.253566  1999 maintenance_manager.cc:643] P 47dba07a335b4b10a16b3ac1330e002e: FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842) complete. Timing: real 0.052s	user 0.026s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23275,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:20:32.254120  2072 maintenance_manager.cc:419] P 47dba07a335b4b10a16b3ac1330e002e: Scheduling FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842): perf score=2.188937
I20260812 06:20:32.267798  1999 maintenance_manager.cc:643] P 47dba07a335b4b10a16b3ac1330e002e: FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842) complete. Timing: real 0.013s	user 0.002s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5258,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:32.268355  2072 maintenance_manager.cc:419] P 47dba07a335b4b10a16b3ac1330e002e: Scheduling FlushMRSOp(f064407d0a5a4f269998a203ab407842): perf score=1.000000
I20260812 06:20:32.299847  1999 maintenance_manager.cc:643] P 47dba07a335b4b10a16b3ac1330e002e: FlushMRSOp(f064407d0a5a4f269998a203ab407842) complete. Timing: real 0.031s	user 0.026s	sys 0.004s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":74,"dirs.run_cpu_time_us":265,"dirs.run_wall_time_us":1252,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1510,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:20:32.300508  2072 maintenance_manager.cc:419] P 47dba07a335b4b10a16b3ac1330e002e: Scheduling LogGCOp(f064407d0a5a4f269998a203ab407842): free 112239259 bytes of WAL
I20260812 06:20:32.300750  1999 log_reader.cc:385] T f064407d0a5a4f269998a203ab407842: removed 11 log segments from log reader
I20260812 06:20:32.300794  1999 log.cc:1079] T f064407d0a5a4f269998a203ab407842 P 47dba07a335b4b10a16b3ac1330e002e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/f064407d0a5a4f269998a203ab407842/wal-000000003 (ops 12-16)
I20260812 06:20:32.300823  1999 log.cc:1079] T f064407d0a5a4f269998a203ab407842 P 47dba07a335b4b10a16b3ac1330e002e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/f064407d0a5a4f269998a203ab407842/wal-000000004 (ops 17-21)
I20260812 06:20:32.300884  1999 log.cc:1079] T f064407d0a5a4f269998a203ab407842 P 47dba07a335b4b10a16b3ac1330e002e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/f064407d0a5a4f269998a203ab407842/wal-000000005 (ops 22-26)
I20260812 06:20:32.300921  1999 log.cc:1079] T f064407d0a5a4f269998a203ab407842 P 47dba07a335b4b10a16b3ac1330e002e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/f064407d0a5a4f269998a203ab407842/wal-000000006 (ops 27-31)
I20260812 06:20:32.300966  1999 log.cc:1079] T f064407d0a5a4f269998a203ab407842 P 47dba07a335b4b10a16b3ac1330e002e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/f064407d0a5a4f269998a203ab407842/wal-000000007 (ops 32-36)
I20260812 06:20:32.301004  1999 log.cc:1079] T f064407d0a5a4f269998a203ab407842 P 47dba07a335b4b10a16b3ac1330e002e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/f064407d0a5a4f269998a203ab407842/wal-000000008 (ops 37-41)
I20260812 06:20:32.301040  1999 log.cc:1079] T f064407d0a5a4f269998a203ab407842 P 47dba07a335b4b10a16b3ac1330e002e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/f064407d0a5a4f269998a203ab407842/wal-000000009 (ops 42-46)
I20260812 06:20:32.301081  1999 log.cc:1079] T f064407d0a5a4f269998a203ab407842 P 47dba07a335b4b10a16b3ac1330e002e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/f064407d0a5a4f269998a203ab407842/wal-000000010 (ops 47-51)
I20260812 06:20:32.301118  1999 log.cc:1079] T f064407d0a5a4f269998a203ab407842 P 47dba07a335b4b10a16b3ac1330e002e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/f064407d0a5a4f269998a203ab407842/wal-000000011 (ops 52-56)
I20260812 06:20:32.301156  1999 log.cc:1079] T f064407d0a5a4f269998a203ab407842 P 47dba07a335b4b10a16b3ac1330e002e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/f064407d0a5a4f269998a203ab407842/wal-000000012 (ops 57-60)
I20260812 06:20:32.301194  1999 log.cc:1079] T f064407d0a5a4f269998a203ab407842 P 47dba07a335b4b10a16b3ac1330e002e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/f064407d0a5a4f269998a203ab407842/wal-000000013 (ops 61-65)
I20260812 06:20:32.329169  1999 maintenance_manager.cc:643] P 47dba07a335b4b10a16b3ac1330e002e: LogGCOp(f064407d0a5a4f269998a203ab407842) complete. Timing: real 0.028s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:20:32.329910  2072 maintenance_manager.cc:419] P 47dba07a335b4b10a16b3ac1330e002e: Scheduling FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842): perf score=3.181125
I20260812 06:20:32.342862  1999 maintenance_manager.cc:643] P 47dba07a335b4b10a16b3ac1330e002e: FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842) complete. Timing: real 0.013s	user 0.006s	sys 0.006s Metrics: {"bytes_written":5005190,"delete_count":0,"lbm_write_time_us":5022,"lbm_writes_lt_1ms":125,"reinsert_count":0,"update_count":610}
I20260812 06:20:32.343353  2072 maintenance_manager.cc:419] P 47dba07a335b4b10a16b3ac1330e002e: Scheduling LogGCOp(f064407d0a5a4f269998a203ab407842): free 12017983 bytes of WAL
I20260812 06:20:32.343576  1999 log_reader.cc:385] T f064407d0a5a4f269998a203ab407842: removed 1 log segments from log reader
I20260812 06:20:32.343621  1999 log.cc:1079] T f064407d0a5a4f269998a203ab407842 P 47dba07a335b4b10a16b3ac1330e002e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/f064407d0a5a4f269998a203ab407842/wal-000000014 (ops 66-70)
I20260812 06:20:32.345984  1999 maintenance_manager.cc:643] P 47dba07a335b4b10a16b3ac1330e002e: LogGCOp(f064407d0a5a4f269998a203ab407842) complete. Timing: real 0.002s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:20:32.346381  2072 maintenance_manager.cc:419] P 47dba07a335b4b10a16b3ac1330e002e: Scheduling FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842): perf score=2.188937
I20260812 06:20:32.359678  1999 maintenance_manager.cc:643] P 47dba07a335b4b10a16b3ac1330e002e: FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842) complete. Timing: real 0.013s	user 0.002s	sys 0.010s Metrics: {"bytes_written":3200105,"delete_count":0,"lbm_write_time_us":4533,"lbm_writes_lt_1ms":81,"reinsert_count":0,"update_count":390}
I20260812 06:20:32.360235  2072 maintenance_manager.cc:419] P 47dba07a335b4b10a16b3ac1330e002e: Scheduling MajorDeltaCompactionOp(f064407d0a5a4f269998a203ab407842): perf score=1.000000
I20260812 06:20:32.568486  1999 maintenance_manager.cc:643] P 47dba07a335b4b10a16b3ac1330e002e: MajorDeltaCompactionOp(f064407d0a5a4f269998a203ab407842) complete. Timing: real 0.208s	user 0.151s	sys 0.056s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979727,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":785,"lbm_read_time_us":15200,"lbm_reads_lt_1ms":766,"lbm_write_time_us":40084,"lbm_writes_lt_1ms":743,"mutex_wait_us":706,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":16000,"thread_start_us":111,"threads_started":1,"update_count":3500}
I20260812 06:20:32.569347  2072 maintenance_manager.cc:419] P 47dba07a335b4b10a16b3ac1330e002e: Scheduling UndoDeltaBlockGCOp(f064407d0a5a4f269998a203ab407842): 461 bytes on disk
I20260812 06:20:32.570461  1999 maintenance_manager.cc:643] P 47dba07a335b4b10a16b3ac1330e002e: UndoDeltaBlockGCOp(f064407d0a5a4f269998a203ab407842) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":77,"lbm_reads_lt_1ms":4}
I20260812 06:20:32.572108  2072 maintenance_manager.cc:419] P 47dba07a335b4b10a16b3ac1330e002e: Scheduling FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842): perf score=15.087375
I20260812 06:20:32.622066  1999 maintenance_manager.cc:643] P 47dba07a335b4b10a16b3ac1330e002e: FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842) complete. Timing: real 0.050s	user 0.017s	sys 0.032s Metrics: {"bytes_written":16820143,"delete_count":0,"lbm_write_time_us":22397,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:20:32.622690  2072 maintenance_manager.cc:419] P 47dba07a335b4b10a16b3ac1330e002e: Scheduling FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842): perf score=2.188937
I20260812 06:20:32.638422  1999 maintenance_manager.cc:643] P 47dba07a335b4b10a16b3ac1330e002e: FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842) complete. Timing: real 0.015s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4843,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:32.639058  2072 maintenance_manager.cc:419] P 47dba07a335b4b10a16b3ac1330e002e: Scheduling MajorDeltaCompactionOp(f064407d0a5a4f269998a203ab407842): perf score=1.000000
I20260812 06:20:32.800493  1999 maintenance_manager.cc:643] P 47dba07a335b4b10a16b3ac1330e002e: MajorDeltaCompactionOp(f064407d0a5a4f269998a203ab407842) complete. Timing: real 0.161s	user 0.114s	sys 0.041s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774676,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":284,"lbm_read_time_us":9632,"lbm_reads_lt_1ms":564,"lbm_write_time_us":31699,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":23936,"update_count":2500}
I20260812 06:20:32.801185  2072 maintenance_manager.cc:419] P 47dba07a335b4b10a16b3ac1330e002e: Scheduling FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842): perf score=14.095187
I20260812 06:20:32.860229  1999 maintenance_manager.cc:643] P 47dba07a335b4b10a16b3ac1330e002e: FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842) complete. Timing: real 0.059s	user 0.040s	sys 0.005s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":21026,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:32.860791  2072 maintenance_manager.cc:419] P 47dba07a335b4b10a16b3ac1330e002e: Scheduling FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842): perf score=2.188937
I20260812 06:20:32.872853  1999 maintenance_manager.cc:643] P 47dba07a335b4b10a16b3ac1330e002e: FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4323,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:32.873347  2072 maintenance_manager.cc:419] P 47dba07a335b4b10a16b3ac1330e002e: Scheduling MajorDeltaCompactionOp(f064407d0a5a4f269998a203ab407842): perf score=1.000000
I20260812 06:20:33.073915  1999 maintenance_manager.cc:643] P 47dba07a335b4b10a16b3ac1330e002e: MajorDeltaCompactionOp(f064407d0a5a4f269998a203ab407842) complete. Timing: real 0.200s	user 0.125s	sys 0.075s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":148,"lbm_read_time_us":13356,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31902,"lbm_writes_lt_1ms":543,"mutex_wait_us":47,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5504,"update_count":2500}
I20260812 06:20:33.074549  2072 maintenance_manager.cc:419] P 47dba07a335b4b10a16b3ac1330e002e: Scheduling FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842): perf score=14.095187
I20260812 06:20:33.126574  1999 maintenance_manager.cc:643] P 47dba07a335b4b10a16b3ac1330e002e: FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842) complete. Timing: real 0.052s	user 0.030s	sys 0.016s Metrics: {"bytes_written":16409907,"delete_count":0,"lbm_write_time_us":21162,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:33.127100  2072 maintenance_manager.cc:419] P 47dba07a335b4b10a16b3ac1330e002e: Scheduling MajorDeltaCompactionOp(f064407d0a5a4f269998a203ab407842): perf score=1.000000
I20260812 06:20:33.276239  1999 maintenance_manager.cc:643] P 47dba07a335b4b10a16b3ac1330e002e: MajorDeltaCompactionOp(f064407d0a5a4f269998a203ab407842) complete. Timing: real 0.149s	user 0.098s	sys 0.048s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672163,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1031,"lbm_read_time_us":9876,"lbm_reads_lt_1ms":463,"lbm_write_time_us":24913,"lbm_writes_lt_1ms":443,"mutex_wait_us":358,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:20:33.276806  2072 maintenance_manager.cc:419] P 47dba07a335b4b10a16b3ac1330e002e: Scheduling FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842): perf score=14.095187
I20260812 06:20:33.331683  1999 maintenance_manager.cc:643] P 47dba07a335b4b10a16b3ac1330e002e: FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842) complete. Timing: real 0.055s	user 0.033s	sys 0.011s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":20994,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:33.332263  2072 maintenance_manager.cc:419] P 47dba07a335b4b10a16b3ac1330e002e: Scheduling FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842): perf score=2.188937
I20260812 06:20:33.344605  1999 maintenance_manager.cc:643] P 47dba07a335b4b10a16b3ac1330e002e: FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842) complete. Timing: real 0.012s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4179,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:33.345263  2072 maintenance_manager.cc:419] P 47dba07a335b4b10a16b3ac1330e002e: Scheduling MajorDeltaCompactionOp(f064407d0a5a4f269998a203ab407842): perf score=1.000000
I20260812 06:20:33.549692  1999 maintenance_manager.cc:643] P 47dba07a335b4b10a16b3ac1330e002e: MajorDeltaCompactionOp(f064407d0a5a4f269998a203ab407842) complete. Timing: real 0.204s	user 0.121s	sys 0.069s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":754,"lbm_read_time_us":12295,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32879,"lbm_writes_lt_1ms":543,"mutex_wait_us":44,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":62848,"update_count":2500}
I20260812 06:20:33.550473  2072 maintenance_manager.cc:419] P 47dba07a335b4b10a16b3ac1330e002e: Scheduling FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842): perf score=14.095187
I20260812 06:20:33.602473  1999 maintenance_manager.cc:643] P 47dba07a335b4b10a16b3ac1330e002e: FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842) complete. Timing: real 0.052s	user 0.032s	sys 0.018s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23295,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:33.603067  2072 maintenance_manager.cc:419] P 47dba07a335b4b10a16b3ac1330e002e: Scheduling FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842): perf score=2.188937
I20260812 06:20:33.614965  1999 maintenance_manager.cc:643] P 47dba07a335b4b10a16b3ac1330e002e: FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842) complete. Timing: real 0.012s	user 0.009s	sys 0.002s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4198,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:33.615562  2072 maintenance_manager.cc:419] P 47dba07a335b4b10a16b3ac1330e002e: Scheduling MajorDeltaCompactionOp(f064407d0a5a4f269998a203ab407842): perf score=1.000000
I20260812 06:20:33.780936  1999 maintenance_manager.cc:643] P 47dba07a335b4b10a16b3ac1330e002e: MajorDeltaCompactionOp(f064407d0a5a4f269998a203ab407842) complete. Timing: real 0.165s	user 0.118s	sys 0.045s 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":932,"lbm_read_time_us":11342,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32532,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":17536,"update_count":2500}
I20260812 06:20:33.781683  2072 maintenance_manager.cc:419] P 47dba07a335b4b10a16b3ac1330e002e: Scheduling FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842): perf score=10.126437
I20260812 06:20:33.827181  1999 maintenance_manager.cc:643] P 47dba07a335b4b10a16b3ac1330e002e: FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842) complete. Timing: real 0.045s	user 0.027s	sys 0.016s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":20340,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:33.827800  2072 maintenance_manager.cc:419] P 47dba07a335b4b10a16b3ac1330e002e: Scheduling FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842): perf score=2.188937
I20260812 06:20:33.841863  1999 maintenance_manager.cc:643] P 47dba07a335b4b10a16b3ac1330e002e: FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842) complete. Timing: real 0.014s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5403,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:33.842461  2072 maintenance_manager.cc:419] P 47dba07a335b4b10a16b3ac1330e002e: Scheduling FlushMRSOp(f064407d0a5a4f269998a203ab407842): perf score=1.000000
I20260812 06:20:33.874027  1999 maintenance_manager.cc:643] P 47dba07a335b4b10a16b3ac1330e002e: FlushMRSOp(f064407d0a5a4f269998a203ab407842) complete. Timing: real 0.031s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":236,"dirs.run_cpu_time_us":237,"dirs.run_wall_time_us":1532,"drs_written":1,"lbm_read_time_us":107,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1510,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:20:33.874868  2072 maintenance_manager.cc:419] P 47dba07a335b4b10a16b3ac1330e002e: Scheduling LogGCOp(f064407d0a5a4f269998a203ab407842): free 121006392 bytes of WAL
I20260812 06:20:33.875103  1999 log_reader.cc:385] T f064407d0a5a4f269998a203ab407842: removed 12 log segments from log reader
I20260812 06:20:33.875177  1999 log.cc:1079] T f064407d0a5a4f269998a203ab407842 P 47dba07a335b4b10a16b3ac1330e002e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/f064407d0a5a4f269998a203ab407842/wal-000000015 (ops 71-75)
I20260812 06:20:33.875253  1999 log.cc:1079] T f064407d0a5a4f269998a203ab407842 P 47dba07a335b4b10a16b3ac1330e002e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/f064407d0a5a4f269998a203ab407842/wal-000000016 (ops 76-80)
I20260812 06:20:33.875310  1999 log.cc:1079] T f064407d0a5a4f269998a203ab407842 P 47dba07a335b4b10a16b3ac1330e002e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/f064407d0a5a4f269998a203ab407842/wal-000000017 (ops 81-84)
I20260812 06:20:33.875360  1999 log.cc:1079] T f064407d0a5a4f269998a203ab407842 P 47dba07a335b4b10a16b3ac1330e002e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/f064407d0a5a4f269998a203ab407842/wal-000000018 (ops 85-89)
I20260812 06:20:33.875406  1999 log.cc:1079] T f064407d0a5a4f269998a203ab407842 P 47dba07a335b4b10a16b3ac1330e002e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/f064407d0a5a4f269998a203ab407842/wal-000000019 (ops 90-94)
I20260812 06:20:33.875452  1999 log.cc:1079] T f064407d0a5a4f269998a203ab407842 P 47dba07a335b4b10a16b3ac1330e002e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/f064407d0a5a4f269998a203ab407842/wal-000000020 (ops 95-99)
I20260812 06:20:33.875526  1999 log.cc:1079] T f064407d0a5a4f269998a203ab407842 P 47dba07a335b4b10a16b3ac1330e002e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/f064407d0a5a4f269998a203ab407842/wal-000000021 (ops 100-104)
I20260812 06:20:33.875592  1999 log.cc:1079] T f064407d0a5a4f269998a203ab407842 P 47dba07a335b4b10a16b3ac1330e002e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/f064407d0a5a4f269998a203ab407842/wal-000000022 (ops 105-109)
I20260812 06:20:33.875653  1999 log.cc:1079] T f064407d0a5a4f269998a203ab407842 P 47dba07a335b4b10a16b3ac1330e002e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/f064407d0a5a4f269998a203ab407842/wal-000000023 (ops 110-114)
I20260812 06:20:33.875718  1999 log.cc:1079] T f064407d0a5a4f269998a203ab407842 P 47dba07a335b4b10a16b3ac1330e002e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/f064407d0a5a4f269998a203ab407842/wal-000000024 (ops 115-119)
I20260812 06:20:33.875787  1999 log.cc:1079] T f064407d0a5a4f269998a203ab407842 P 47dba07a335b4b10a16b3ac1330e002e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/f064407d0a5a4f269998a203ab407842/wal-000000025 (ops 120-124)
I20260812 06:20:33.875852  1999 log.cc:1079] T f064407d0a5a4f269998a203ab407842 P 47dba07a335b4b10a16b3ac1330e002e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/f064407d0a5a4f269998a203ab407842/wal-000000026 (ops 125-129)
I20260812 06:20:33.906275  1999 maintenance_manager.cc:643] P 47dba07a335b4b10a16b3ac1330e002e: LogGCOp(f064407d0a5a4f269998a203ab407842) complete. Timing: real 0.031s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:20:33.906754  2072 maintenance_manager.cc:419] P 47dba07a335b4b10a16b3ac1330e002e: Scheduling FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842): perf score=4.173312
I20260812 06:20:33.925429  1999 maintenance_manager.cc:643] P 47dba07a335b4b10a16b3ac1330e002e: FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842) complete. Timing: real 0.018s	user 0.012s	sys 0.004s Metrics: {"bytes_written":5620561,"delete_count":0,"lbm_write_time_us":7656,"lbm_writes_lt_1ms":140,"reinsert_count":0,"update_count":685}
I20260812 06:20:33.926167  2072 maintenance_manager.cc:419] P 47dba07a335b4b10a16b3ac1330e002e: Scheduling UndoDeltaBlockGCOp(f064407d0a5a4f269998a203ab407842): 471 bytes on disk
I20260812 06:20:33.926613  1999 maintenance_manager.cc:643] P 47dba07a335b4b10a16b3ac1330e002e: UndoDeltaBlockGCOp(f064407d0a5a4f269998a203ab407842) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4}
I20260812 06:20:33.927114  2072 maintenance_manager.cc:419] P 47dba07a335b4b10a16b3ac1330e002e: Scheduling FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842): perf score=1.196750
I20260812 06:20:33.936139  1999 maintenance_manager.cc:643] P 47dba07a335b4b10a16b3ac1330e002e: FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842) complete. Timing: real 0.009s	user 0.004s	sys 0.003s Metrics: {"bytes_written":2584729,"delete_count":0,"lbm_write_time_us":2999,"lbm_writes_lt_1ms":66,"reinsert_count":0,"update_count":315}
I20260812 06:20:33.936630  2072 maintenance_manager.cc:419] P 47dba07a335b4b10a16b3ac1330e002e: Scheduling MajorDeltaCompactionOp(f064407d0a5a4f269998a203ab407842): perf score=1.000000
I20260812 06:20:34.163419  1999 maintenance_manager.cc:643] P 47dba07a335b4b10a16b3ac1330e002e: MajorDeltaCompactionOp(f064407d0a5a4f269998a203ab407842) complete. Timing: real 0.227s	user 0.157s	sys 0.052s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877303,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":17808,"lbm_read_time_us":14135,"lbm_reads_lt_1ms":674,"lbm_write_time_us":35750,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2176,"thread_start_us":8298,"threads_started":1,"update_count":3000}
I20260812 06:20:34.164062  2072 maintenance_manager.cc:419] P 47dba07a335b4b10a16b3ac1330e002e: Scheduling FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842): perf score=15.087375
I20260812 06:20:34.212903  1999 maintenance_manager.cc:643] P 47dba07a335b4b10a16b3ac1330e002e: FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842) complete. Timing: real 0.049s	user 0.029s	sys 0.016s Metrics: {"bytes_written":16820145,"delete_count":0,"lbm_write_time_us":22154,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:20:34.213438  2072 maintenance_manager.cc:419] P 47dba07a335b4b10a16b3ac1330e002e: Scheduling FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842): perf score=2.188937
I20260812 06:20:34.242375  1999 maintenance_manager.cc:643] P 47dba07a335b4b10a16b3ac1330e002e: FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842) complete. Timing: real 0.029s	user 0.006s	sys 0.021s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5888,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:34.243429  2072 maintenance_manager.cc:419] P 47dba07a335b4b10a16b3ac1330e002e: Scheduling FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842): perf score=1.000000
I20260812 06:20:34.255894  1999 maintenance_manager.cc:643] P 47dba07a335b4b10a16b3ac1330e002e: FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842) complete. Timing: real 0.012s	user 0.005s	sys 0.001s Metrics: {"bytes_written":1271931,"delete_count":0,"lbm_write_time_us":2161,"lbm_writes_lt_1ms":34,"reinsert_count":0,"update_count":155}
I20260812 06:20:34.256672  2072 maintenance_manager.cc:419] P 47dba07a335b4b10a16b3ac1330e002e: Scheduling FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842): perf score=1.196750
I20260812 06:20:34.271396  1999 maintenance_manager.cc:643] P 47dba07a335b4b10a16b3ac1330e002e: FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":2830880,"delete_count":0,"lbm_write_time_us":4987,"lbm_writes_lt_1ms":72,"reinsert_count":0,"update_count":345}
I20260812 06:20:34.272105  2072 maintenance_manager.cc:419] P 47dba07a335b4b10a16b3ac1330e002e: Scheduling MajorDeltaCompactionOp(f064407d0a5a4f269998a203ab407842): perf score=1.000000
I20260812 06:20:34.518077  1999 maintenance_manager.cc:643] P 47dba07a335b4b10a16b3ac1330e002e: MajorDeltaCompactionOp(f064407d0a5a4f269998a203ab407842) complete. Timing: real 0.246s	user 0.170s	sys 0.075s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877234,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":245,"lbm_read_time_us":20144,"lbm_reads_lt_1ms":674,"lbm_write_time_us":39402,"lbm_writes_lt_1ms":643,"mutex_wait_us":18,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":13184,"update_count":3000}
I20260812 06:20:34.518895  2072 maintenance_manager.cc:419] P 47dba07a335b4b10a16b3ac1330e002e: Scheduling FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842): perf score=14.095187
I20260812 06:20:34.590512  1999 maintenance_manager.cc:643] P 47dba07a335b4b10a16b3ac1330e002e: FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842) complete. Timing: real 0.071s	user 0.019s	sys 0.043s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":27813,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:20:34.591100  2072 maintenance_manager.cc:419] P 47dba07a335b4b10a16b3ac1330e002e: Scheduling FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842): perf score=2.188937
I20260812 06:20:34.602077  1999 maintenance_manager.cc:643] P 47dba07a335b4b10a16b3ac1330e002e: FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4216,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:34.602571  2072 maintenance_manager.cc:419] P 47dba07a335b4b10a16b3ac1330e002e: Scheduling MajorDeltaCompactionOp(f064407d0a5a4f269998a203ab407842): perf score=1.000000
I20260812 06:20:34.790159  1999 maintenance_manager.cc:643] P 47dba07a335b4b10a16b3ac1330e002e: MajorDeltaCompactionOp(f064407d0a5a4f269998a203ab407842) complete. Timing: real 0.187s	user 0.114s	sys 0.072s 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":414,"lbm_read_time_us":13097,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31898,"lbm_writes_lt_1ms":543,"mutex_wait_us":59,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":20352,"update_count":2500}
I20260812 06:20:34.790928  2072 maintenance_manager.cc:419] P 47dba07a335b4b10a16b3ac1330e002e: Scheduling FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842): perf score=10.126437
I20260812 06:20:34.836052  1999 maintenance_manager.cc:643] P 47dba07a335b4b10a16b3ac1330e002e: FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842) complete. Timing: real 0.045s	user 0.019s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18707,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:34.836719  2072 maintenance_manager.cc:419] P 47dba07a335b4b10a16b3ac1330e002e: Scheduling FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842): perf score=2.188937
I20260812 06:20:34.848842  1999 maintenance_manager.cc:643] P 47dba07a335b4b10a16b3ac1330e002e: FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842) complete. Timing: real 0.012s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4673,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:34.849565  2072 maintenance_manager.cc:419] P 47dba07a335b4b10a16b3ac1330e002e: Scheduling MajorDeltaCompactionOp(f064407d0a5a4f269998a203ab407842): perf score=1.000000
I20260812 06:20:35.018498  1999 maintenance_manager.cc:643] P 47dba07a335b4b10a16b3ac1330e002e: MajorDeltaCompactionOp(f064407d0a5a4f269998a203ab407842) complete. Timing: real 0.169s	user 0.096s	sys 0.065s 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":970,"lbm_read_time_us":9403,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28282,"lbm_writes_lt_1ms":443,"mutex_wait_us":82,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2000}
I20260812 06:20:35.019200  2072 maintenance_manager.cc:419] P 47dba07a335b4b10a16b3ac1330e002e: Scheduling FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842): perf score=11.118625
I20260812 06:20:35.063016  1999 maintenance_manager.cc:643] P 47dba07a335b4b10a16b3ac1330e002e: FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842) complete. Timing: real 0.044s	user 0.026s	sys 0.015s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":18926,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:20:35.063732  2072 maintenance_manager.cc:419] P 47dba07a335b4b10a16b3ac1330e002e: Scheduling FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842): perf score=2.188937
I20260812 06:20:35.080590  1999 maintenance_manager.cc:643] P 47dba07a335b4b10a16b3ac1330e002e: FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842) complete. Timing: real 0.017s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4876,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:35.081316  2072 maintenance_manager.cc:419] P 47dba07a335b4b10a16b3ac1330e002e: Scheduling MajorDeltaCompactionOp(f064407d0a5a4f269998a203ab407842): perf score=1.000000
I20260812 06:20:35.213599  1999 maintenance_manager.cc:643] P 47dba07a335b4b10a16b3ac1330e002e: MajorDeltaCompactionOp(f064407d0a5a4f269998a203ab407842) complete. Timing: real 0.132s	user 0.096s	sys 0.036s 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":437,"lbm_read_time_us":9260,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25362,"lbm_writes_lt_1ms":443,"mutex_wait_us":84,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12032,"update_count":2000}
I20260812 06:20:35.214519  2072 maintenance_manager.cc:419] P 47dba07a335b4b10a16b3ac1330e002e: Scheduling FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842): perf score=10.126437
I20260812 06:20:35.261373  1999 maintenance_manager.cc:643] P 47dba07a335b4b10a16b3ac1330e002e: FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842) complete. Timing: real 0.047s	user 0.021s	sys 0.015s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":17256,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:35.261986  2072 maintenance_manager.cc:419] P 47dba07a335b4b10a16b3ac1330e002e: Scheduling FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842): perf score=2.188937
I20260812 06:20:35.273916  1999 maintenance_manager.cc:643] P 47dba07a335b4b10a16b3ac1330e002e: FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4207,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:35.274597  2072 maintenance_manager.cc:419] P 47dba07a335b4b10a16b3ac1330e002e: Scheduling MajorDeltaCompactionOp(f064407d0a5a4f269998a203ab407842): perf score=1.000000
I20260812 06:20:35.414832  1999 maintenance_manager.cc:643] P 47dba07a335b4b10a16b3ac1330e002e: MajorDeltaCompactionOp(f064407d0a5a4f269998a203ab407842) complete. Timing: real 0.140s	user 0.127s	sys 0.012s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672280,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":843,"lbm_read_time_us":9767,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28152,"lbm_writes_lt_1ms":443,"mutex_wait_us":276,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5376,"update_count":2000}
I20260812 06:20:35.415428  2072 maintenance_manager.cc:419] P 47dba07a335b4b10a16b3ac1330e002e: Scheduling FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842): perf score=10.126437
I20260812 06:20:35.468827  1999 maintenance_manager.cc:643] P 47dba07a335b4b10a16b3ac1330e002e: FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842) complete. Timing: real 0.053s	user 0.014s	sys 0.034s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":19409,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:20:35.469468  2072 maintenance_manager.cc:419] P 47dba07a335b4b10a16b3ac1330e002e: Scheduling FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842): perf score=2.188937
I20260812 06:20:35.480540  1999 maintenance_manager.cc:643] P 47dba07a335b4b10a16b3ac1330e002e: FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4266,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:35.481117  2072 maintenance_manager.cc:419] P 47dba07a335b4b10a16b3ac1330e002e: Scheduling FlushMRSOp(f064407d0a5a4f269998a203ab407842): perf score=1.000000
I20260812 06:20:35.528798  1999 maintenance_manager.cc:643] P 47dba07a335b4b10a16b3ac1330e002e: FlushMRSOp(f064407d0a5a4f269998a203ab407842) complete. Timing: real 0.047s	user 0.034s	sys 0.000s Metrics: {"bytes_written":1193505,"cfile_init":1,"dirs.queue_time_us":66,"dirs.run_cpu_time_us":245,"dirs.run_wall_time_us":1467,"drs_written":1,"lbm_read_time_us":74,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1476,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:20:35.529533  2072 maintenance_manager.cc:419] P 47dba07a335b4b10a16b3ac1330e002e: Scheduling LogGCOp(f064407d0a5a4f269998a203ab407842): free 120100649 bytes of WAL
I20260812 06:20:35.529834  1999 log_reader.cc:385] T f064407d0a5a4f269998a203ab407842: removed 12 log segments from log reader
I20260812 06:20:35.529884  1999 log.cc:1079] T f064407d0a5a4f269998a203ab407842 P 47dba07a335b4b10a16b3ac1330e002e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/f064407d0a5a4f269998a203ab407842/wal-000000027 (ops 130-134)
I20260812 06:20:35.529937  1999 log.cc:1079] T f064407d0a5a4f269998a203ab407842 P 47dba07a335b4b10a16b3ac1330e002e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/f064407d0a5a4f269998a203ab407842/wal-000000028 (ops 135-139)
I20260812 06:20:35.529985  1999 log.cc:1079] T f064407d0a5a4f269998a203ab407842 P 47dba07a335b4b10a16b3ac1330e002e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/f064407d0a5a4f269998a203ab407842/wal-000000029 (ops 140-144)
I20260812 06:20:35.530025  1999 log.cc:1079] T f064407d0a5a4f269998a203ab407842 P 47dba07a335b4b10a16b3ac1330e002e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/f064407d0a5a4f269998a203ab407842/wal-000000030 (ops 145-148)
I20260812 06:20:35.530067  1999 log.cc:1079] T f064407d0a5a4f269998a203ab407842 P 47dba07a335b4b10a16b3ac1330e002e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/f064407d0a5a4f269998a203ab407842/wal-000000031 (ops 149-153)
I20260812 06:20:35.530108  1999 log.cc:1079] T f064407d0a5a4f269998a203ab407842 P 47dba07a335b4b10a16b3ac1330e002e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/f064407d0a5a4f269998a203ab407842/wal-000000032 (ops 154-158)
I20260812 06:20:35.530146  1999 log.cc:1079] T f064407d0a5a4f269998a203ab407842 P 47dba07a335b4b10a16b3ac1330e002e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/f064407d0a5a4f269998a203ab407842/wal-000000033 (ops 159-162)
I20260812 06:20:35.530187  1999 log.cc:1079] T f064407d0a5a4f269998a203ab407842 P 47dba07a335b4b10a16b3ac1330e002e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/f064407d0a5a4f269998a203ab407842/wal-000000034 (ops 163-167)
I20260812 06:20:35.530229  1999 log.cc:1079] T f064407d0a5a4f269998a203ab407842 P 47dba07a335b4b10a16b3ac1330e002e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/f064407d0a5a4f269998a203ab407842/wal-000000035 (ops 168-172)
I20260812 06:20:35.530272  1999 log.cc:1079] T f064407d0a5a4f269998a203ab407842 P 47dba07a335b4b10a16b3ac1330e002e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/f064407d0a5a4f269998a203ab407842/wal-000000036 (ops 173-176)
I20260812 06:20:35.530311  1999 log.cc:1079] T f064407d0a5a4f269998a203ab407842 P 47dba07a335b4b10a16b3ac1330e002e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/f064407d0a5a4f269998a203ab407842/wal-000000037 (ops 177-181)
I20260812 06:20:35.530352  1999 log.cc:1079] T f064407d0a5a4f269998a203ab407842 P 47dba07a335b4b10a16b3ac1330e002e: Deleting log segment in path: /tmp/dist-test-taskUInCqA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624860936-1664-0/minicluster-data/ts-0-root/wals/f064407d0a5a4f269998a203ab407842/wal-000000038 (ops 182-186)
I20260812 06:20:35.557391  1999 maintenance_manager.cc:643] P 47dba07a335b4b10a16b3ac1330e002e: LogGCOp(f064407d0a5a4f269998a203ab407842) complete. Timing: real 0.028s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:20:35.558022  2072 maintenance_manager.cc:419] P 47dba07a335b4b10a16b3ac1330e002e: Scheduling UndoDeltaBlockGCOp(f064407d0a5a4f269998a203ab407842): 463 bytes on disk
I20260812 06:20:35.558787  1999 maintenance_manager.cc:643] P 47dba07a335b4b10a16b3ac1330e002e: UndoDeltaBlockGCOp(f064407d0a5a4f269998a203ab407842) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":118,"lbm_reads_lt_1ms":4}
I20260812 06:20:35.559773  2072 maintenance_manager.cc:419] P 47dba07a335b4b10a16b3ac1330e002e: Scheduling FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842): perf score=3.181125
I20260812 06:20:35.583850  1999 maintenance_manager.cc:643] P 47dba07a335b4b10a16b3ac1330e002e: FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842) complete. Timing: real 0.024s	user 0.008s	sys 0.008s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":7572,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:35.584470  2072 maintenance_manager.cc:419] P 47dba07a335b4b10a16b3ac1330e002e: Scheduling FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842): perf score=2.188937
I20260812 06:20:35.599292  1999 maintenance_manager.cc:643] P 47dba07a335b4b10a16b3ac1330e002e: FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842) complete. Timing: real 0.015s	user 0.004s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5455,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:35.599932  2072 maintenance_manager.cc:419] P 47dba07a335b4b10a16b3ac1330e002e: Scheduling MajorDeltaCompactionOp(f064407d0a5a4f269998a203ab407842): perf score=1.000000
I20260812 06:20:35.823911  1999 maintenance_manager.cc:643] P 47dba07a335b4b10a16b3ac1330e002e: MajorDeltaCompactionOp(f064407d0a5a4f269998a203ab407842) complete. Timing: real 0.224s	user 0.155s	sys 0.068s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877325,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":120,"lbm_read_time_us":15438,"lbm_reads_lt_1ms":674,"lbm_write_time_us":36676,"lbm_writes_lt_1ms":643,"mutex_wait_us":42,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1792,"thread_start_us":119,"threads_started":1,"update_count":3000}
I20260812 06:20:35.824515  2072 maintenance_manager.cc:419] P 47dba07a335b4b10a16b3ac1330e002e: Scheduling FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842): perf score=14.095187
I20260812 06:20:35.868564  1999 maintenance_manager.cc:643] P 47dba07a335b4b10a16b3ac1330e002e: FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842) complete. Timing: real 0.044s	user 0.011s	sys 0.028s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19075,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:35.869094  2072 maintenance_manager.cc:419] P 47dba07a335b4b10a16b3ac1330e002e: Scheduling FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842): perf score=2.188937
I20260812 06:20:35.880460  1999 maintenance_manager.cc:643] P 47dba07a335b4b10a16b3ac1330e002e: FlushDeltaMemStoresOp(f064407d0a5a4f269998a203ab407842) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4608,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:35.880942  2072 maintenance_manager.cc:419] P 47dba07a335b4b10a16b3ac1330e002e: Scheduling MajorDeltaCompactionOp(f064407d0a5a4f269998a203ab407842): perf score=1.000000
I20260812 06:20:35.917984  1664 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.216s	user 1.875s	sys 0.184s
I20260812 06:20:35.993172  1664 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.075s	user 0.001s	sys 0.000s
I20260812 06:20:35.993759  1664 tablet_server.cc:179] TabletServer@127.1.160.1:0 shutting down...
I20260812 06:20:36.042248  1999 maintenance_manager.cc:643] P 47dba07a335b4b10a16b3ac1330e002e: MajorDeltaCompactionOp(f064407d0a5a4f269998a203ab407842) complete. Timing: real 0.161s	user 0.117s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":415,"lbm_read_time_us":11772,"lbm_reads_lt_1ms":568,"lbm_write_time_us":27168,"lbm_writes_lt_1ms":543,"mutex_wait_us":73,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:20:36.042985  1664 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:20:36.043229  1664 tablet_replica.cc:333] T f064407d0a5a4f269998a203ab407842 P 47dba07a335b4b10a16b3ac1330e002e: stopping tablet replica
I20260812 06:20:36.043381  1664 raft_consensus.cc:2243] T f064407d0a5a4f269998a203ab407842 P 47dba07a335b4b10a16b3ac1330e002e [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:36.043583  1664 raft_consensus.cc:2272] T f064407d0a5a4f269998a203ab407842 P 47dba07a335b4b10a16b3ac1330e002e [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:36.050194  1664 tablet_server.cc:196] TabletServer@127.1.160.1:0 shutdown complete.
I20260812 06:20:36.090642  1664 master.cc:562] Master@127.1.160.62:38245 shutting down...
I20260812 06:20:36.094548  1664 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 8d005205855a4c589a4ca84db45bdf52 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:36.094785  1664 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 8d005205855a4c589a4ca84db45bdf52 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:36.094877  1664 tablet_replica.cc:333] T 00000000000000000000000000000000 P 8d005205855a4c589a4ca84db45bdf52: stopping tablet replica
I20260812 06:20:36.107474  1664 master.cc:584] Master@127.1.160.62:38245 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5743 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11326 ms total)

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