[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:18:31.793813 26815 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.26.47.254:42419
I20260812 06:18:31.794873 26815 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:18:31.795486 26815 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:31.802649 26826 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:31.802685 26827 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:31.802851 26815 server_base.cc:1061] running on GCE node
W20260812 06:18:31.802976 26830 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:31.803503 26815 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:31.803597 26815 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:31.803627 26815 hybrid_clock.cc:648] HybridClock initialized: now 1786515511803626 us; error 0 us; skew 500 ppm
I20260812 06:18:31.805445 26815 webserver.cc:533] Webserver started at http://127.26.47.254:34319/ using document root <none> and password file <none>
I20260812 06:18:31.806025 26815 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:31.806083 26815 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:31.806284 26815 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:31.807988 26815 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515511783042-26815-0/minicluster-data/master-0-root/instance:
uuid: "968c93097add4f36af1583ef86391d58"
format_stamp: "Formatted at 2026-08-12 06:18:31 on dist-test-slave-gsp7"
I20260812 06:18:31.811741 26815 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.005s	sys 0.000s
I20260812 06:18:31.813962 26842 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:31.815016 26815 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:18:31.815169 26815 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515511783042-26815-0/minicluster-data/master-0-root
uuid: "968c93097add4f36af1583ef86391d58"
format_stamp: "Formatted at 2026-08-12 06:18:31 on dist-test-slave-gsp7"
I20260812 06:18:31.815282 26815 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515511783042-26815-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515511783042-26815-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515511783042-26815-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:31.840057 26815 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:31.840791 26815 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:18:31.840991 26815 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:31.848925 26934 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.26.47.254:42419 every 8 connection(s)
I20260812 06:18:31.848943 26815 rpc_server.cc:307] RPC server started. Bound to: 127.26.47.254:42419
I20260812 06:18:31.851420 26936 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:31.857067 26936 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 968c93097add4f36af1583ef86391d58: Bootstrap starting.
I20260812 06:18:31.859690 26936 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 968c93097add4f36af1583ef86391d58: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:31.860683 26936 log.cc:826] T 00000000000000000000000000000000 P 968c93097add4f36af1583ef86391d58: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:31.862519 26936 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 968c93097add4f36af1583ef86391d58: No bootstrap required, opened a new log
I20260812 06:18:31.865528 26936 raft_consensus.cc:359] T 00000000000000000000000000000000 P 968c93097add4f36af1583ef86391d58 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "968c93097add4f36af1583ef86391d58" member_type: VOTER }
I20260812 06:18:31.865744 26936 raft_consensus.cc:385] T 00000000000000000000000000000000 P 968c93097add4f36af1583ef86391d58 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:31.865850 26936 raft_consensus.cc:740] T 00000000000000000000000000000000 P 968c93097add4f36af1583ef86391d58 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 968c93097add4f36af1583ef86391d58, State: Initialized, Role: FOLLOWER
I20260812 06:18:31.866609 26936 consensus_queue.cc:260] T 00000000000000000000000000000000 P 968c93097add4f36af1583ef86391d58 [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: "968c93097add4f36af1583ef86391d58" member_type: VOTER }
I20260812 06:18:31.866791 26936 raft_consensus.cc:399] T 00000000000000000000000000000000 P 968c93097add4f36af1583ef86391d58 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:31.866863 26936 raft_consensus.cc:493] T 00000000000000000000000000000000 P 968c93097add4f36af1583ef86391d58 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:31.867004 26936 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 968c93097add4f36af1583ef86391d58 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:31.867909 26936 raft_consensus.cc:515] T 00000000000000000000000000000000 P 968c93097add4f36af1583ef86391d58 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "968c93097add4f36af1583ef86391d58" member_type: VOTER }
I20260812 06:18:31.868384 26936 leader_election.cc:304] T 00000000000000000000000000000000 P 968c93097add4f36af1583ef86391d58 [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: 968c93097add4f36af1583ef86391d58; no voters: 
I20260812 06:18:31.868753 26936 leader_election.cc:290] T 00000000000000000000000000000000 P 968c93097add4f36af1583ef86391d58 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:31.868943 26942 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 968c93097add4f36af1583ef86391d58 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:31.869199 26942 raft_consensus.cc:697] T 00000000000000000000000000000000 P 968c93097add4f36af1583ef86391d58 [term 1 LEADER]: Becoming Leader. State: Replica: 968c93097add4f36af1583ef86391d58, State: Running, Role: LEADER
I20260812 06:18:31.869702 26942 consensus_queue.cc:237] T 00000000000000000000000000000000 P 968c93097add4f36af1583ef86391d58 [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: "968c93097add4f36af1583ef86391d58" member_type: VOTER }
I20260812 06:18:31.869923 26936 sys_catalog.cc:565] T 00000000000000000000000000000000 P 968c93097add4f36af1583ef86391d58 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:31.871755 26944 sys_catalog.cc:455] T 00000000000000000000000000000000 P 968c93097add4f36af1583ef86391d58 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 968c93097add4f36af1583ef86391d58. Latest consensus state: current_term: 1 leader_uuid: "968c93097add4f36af1583ef86391d58" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "968c93097add4f36af1583ef86391d58" member_type: VOTER } }
I20260812 06:18:31.871798 26943 sys_catalog.cc:455] T 00000000000000000000000000000000 P 968c93097add4f36af1583ef86391d58 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "968c93097add4f36af1583ef86391d58" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "968c93097add4f36af1583ef86391d58" member_type: VOTER } }
I20260812 06:18:31.871897 26943 sys_catalog.cc:458] T 00000000000000000000000000000000 P 968c93097add4f36af1583ef86391d58 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:31.871897 26944 sys_catalog.cc:458] T 00000000000000000000000000000000 P 968c93097add4f36af1583ef86391d58 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:31.872339 26815 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:31.872303 26963 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:31.875078 26963 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:31.880223 26963 catalog_manager.cc:1383] Generated new cluster ID: 58c92c02aff640eb83e4af402455c011
I20260812 06:18:31.880313 26963 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:31.896739 26963 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:31.897719 26963 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:31.905314 26963 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 968c93097add4f36af1583ef86391d58: Generated new TSK 0
I20260812 06:18:31.906098 26963 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:31.937544 26815 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:31.940469 26979 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:31.940574 26983 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:31.940470 26976 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:31.940827 26815 server_base.cc:1061] running on GCE node
I20260812 06:18:31.941115 26815 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:31.941172 26815 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:31.941206 26815 hybrid_clock.cc:648] HybridClock initialized: now 1786515511941206 us; error 0 us; skew 500 ppm
I20260812 06:18:31.942216 26815 webserver.cc:533] Webserver started at http://127.26.47.193:37647/ using document root <none> and password file <none>
I20260812 06:18:31.942389 26815 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:31.942461 26815 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:31.942540 26815 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:31.943017 26815 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515511783042-26815-0/minicluster-data/ts-0-root/instance:
uuid: "4e070d2fb6f8495fb5d07d3dd69d4b9e"
format_stamp: "Formatted at 2026-08-12 06:18:31 on dist-test-slave-gsp7"
I20260812 06:18:31.944891 26815 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.001s	sys 0.002s
I20260812 06:18:31.946043 26991 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:31.946347 26815 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.000s
I20260812 06:18:31.946419 26815 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515511783042-26815-0/minicluster-data/ts-0-root
uuid: "4e070d2fb6f8495fb5d07d3dd69d4b9e"
format_stamp: "Formatted at 2026-08-12 06:18:31 on dist-test-slave-gsp7"
I20260812 06:18:31.946511 26815 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515511783042-26815-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515511783042-26815-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515511783042-26815-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:31.961879 26815 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:31.962399 26815 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:31.962910 26815 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:31.963858 26815 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:31.963914 26815 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:31.963987 26815 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:31.964022 26815 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:31.971240 26815 rpc_server.cc:307] RPC server started. Bound to: 127.26.47.193:45305
I20260812 06:18:31.971310 27095 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.26.47.193:45305 every 8 connection(s)
I20260812 06:18:31.985149 27096 heartbeater.cc:344] Connected to a master server at 127.26.47.254:42419
I20260812 06:18:31.985455 27096 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:31.986006 27096 heartbeater.cc:507] Master 127.26.47.254:42419 requested a full tablet report, sending...
I20260812 06:18:31.987468 26871 ts_manager.cc:194] Registered new tserver with Master: 4e070d2fb6f8495fb5d07d3dd69d4b9e (127.26.47.193:45305)
I20260812 06:18:31.987811 26815 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.015769886s
I20260812 06:18:31.988732 26871 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:36916
I20260812 06:18:31.998005 26871 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:36920:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:32.012578 27034 tablet_service.cc:1511] Processing CreateTablet for tablet c0d97839b0f24b7a8ee5a5877b8b2029 (DEFAULT_TABLE table=heavy-update-compaction-test [id=9a516cb24f7841159d6467054f5a64d9]), partition=
I20260812 06:18:32.013082 27034 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet c0d97839b0f24b7a8ee5a5877b8b2029. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:32.016360 27117 tablet_bootstrap.cc:492] T c0d97839b0f24b7a8ee5a5877b8b2029 P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Bootstrap starting.
I20260812 06:18:32.017560 27117 tablet_bootstrap.cc:654] T c0d97839b0f24b7a8ee5a5877b8b2029 P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:32.019495 27117 tablet_bootstrap.cc:492] T c0d97839b0f24b7a8ee5a5877b8b2029 P 4e070d2fb6f8495fb5d07d3dd69d4b9e: No bootstrap required, opened a new log
I20260812 06:18:32.019613 27117 ts_tablet_manager.cc:1403] T c0d97839b0f24b7a8ee5a5877b8b2029 P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Time spent bootstrapping tablet: real 0.003s	user 0.000s	sys 0.003s
I20260812 06:18:32.020254 27117 raft_consensus.cc:359] T c0d97839b0f24b7a8ee5a5877b8b2029 P 4e070d2fb6f8495fb5d07d3dd69d4b9e [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4e070d2fb6f8495fb5d07d3dd69d4b9e" member_type: VOTER last_known_addr { host: "127.26.47.193" port: 45305 } }
I20260812 06:18:32.020385 27117 raft_consensus.cc:385] T c0d97839b0f24b7a8ee5a5877b8b2029 P 4e070d2fb6f8495fb5d07d3dd69d4b9e [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:32.020437 27117 raft_consensus.cc:740] T c0d97839b0f24b7a8ee5a5877b8b2029 P 4e070d2fb6f8495fb5d07d3dd69d4b9e [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 4e070d2fb6f8495fb5d07d3dd69d4b9e, State: Initialized, Role: FOLLOWER
I20260812 06:18:32.020583 27117 consensus_queue.cc:260] T c0d97839b0f24b7a8ee5a5877b8b2029 P 4e070d2fb6f8495fb5d07d3dd69d4b9e [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: "4e070d2fb6f8495fb5d07d3dd69d4b9e" member_type: VOTER last_known_addr { host: "127.26.47.193" port: 45305 } }
I20260812 06:18:32.020691 27117 raft_consensus.cc:399] T c0d97839b0f24b7a8ee5a5877b8b2029 P 4e070d2fb6f8495fb5d07d3dd69d4b9e [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:32.020740 27117 raft_consensus.cc:493] T c0d97839b0f24b7a8ee5a5877b8b2029 P 4e070d2fb6f8495fb5d07d3dd69d4b9e [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:32.020790 27117 raft_consensus.cc:3060] T c0d97839b0f24b7a8ee5a5877b8b2029 P 4e070d2fb6f8495fb5d07d3dd69d4b9e [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:32.021914 27117 raft_consensus.cc:515] T c0d97839b0f24b7a8ee5a5877b8b2029 P 4e070d2fb6f8495fb5d07d3dd69d4b9e [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4e070d2fb6f8495fb5d07d3dd69d4b9e" member_type: VOTER last_known_addr { host: "127.26.47.193" port: 45305 } }
I20260812 06:18:32.022074 27117 leader_election.cc:304] T c0d97839b0f24b7a8ee5a5877b8b2029 P 4e070d2fb6f8495fb5d07d3dd69d4b9e [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: 4e070d2fb6f8495fb5d07d3dd69d4b9e; no voters: 
I20260812 06:18:32.022312 27117 leader_election.cc:290] T c0d97839b0f24b7a8ee5a5877b8b2029 P 4e070d2fb6f8495fb5d07d3dd69d4b9e [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:32.022440 27122 raft_consensus.cc:2804] T c0d97839b0f24b7a8ee5a5877b8b2029 P 4e070d2fb6f8495fb5d07d3dd69d4b9e [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:32.022691 27122 raft_consensus.cc:697] T c0d97839b0f24b7a8ee5a5877b8b2029 P 4e070d2fb6f8495fb5d07d3dd69d4b9e [term 1 LEADER]: Becoming Leader. State: Replica: 4e070d2fb6f8495fb5d07d3dd69d4b9e, State: Running, Role: LEADER
I20260812 06:18:32.022725 27117 ts_tablet_manager.cc:1434] T c0d97839b0f24b7a8ee5a5877b8b2029 P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:32.022900 27122 consensus_queue.cc:237] T c0d97839b0f24b7a8ee5a5877b8b2029 P 4e070d2fb6f8495fb5d07d3dd69d4b9e [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: "4e070d2fb6f8495fb5d07d3dd69d4b9e" member_type: VOTER last_known_addr { host: "127.26.47.193" port: 45305 } }
I20260812 06:18:32.023088 27096 heartbeater.cc:499] Master 127.26.47.254:42419 was elected leader, sending a full tablet report...
I20260812 06:18:32.025629 26871 catalog_manager.cc:5719] T c0d97839b0f24b7a8ee5a5877b8b2029 P 4e070d2fb6f8495fb5d07d3dd69d4b9e reported cstate change: term changed from 0 to 1, leader changed from <none> to 4e070d2fb6f8495fb5d07d3dd69d4b9e (127.26.47.193). New cstate: current_term: 1 leader_uuid: "4e070d2fb6f8495fb5d07d3dd69d4b9e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4e070d2fb6f8495fb5d07d3dd69d4b9e" member_type: VOTER last_known_addr { host: "127.26.47.193" port: 45305 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:32.091172 26815 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.056s	user 0.016s	sys 0.010s
I20260812 06:18:32.222491 27098 maintenance_manager.cc:419] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Scheduling FlushMRSOp(c0d97839b0f24b7a8ee5a5877b8b2029): perf score=19.054940
I20260812 06:18:32.423327 27000 maintenance_manager.cc:643] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: FlushMRSOp(c0d97839b0f24b7a8ee5a5877b8b2029) complete. Timing: real 0.200s	user 0.146s	sys 0.040s Metrics: {"bytes_written":12307490,"cfile_init":1,"compiler_manager_pool.queue_time_us":59533,"compiler_manager_pool.run_cpu_time_us":191532,"compiler_manager_pool.run_wall_time_us":192428,"delete_count":0,"dirs.queue_time_us":98,"dirs.run_cpu_time_us":267,"dirs.run_wall_time_us":888,"drs_written":1,"lbm_read_time_us":80,"lbm_reads_lt_1ms":4,"lbm_write_time_us":48922,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":172,"threads_started":1,"update_count":1500}
I20260812 06:18:32.424612 27098 maintenance_manager.cc:419] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Scheduling LogGCOp(c0d97839b0f24b7a8ee5a5877b8b2029): free 20743880 bytes of WAL
I20260812 06:18:32.424955 27000 log_reader.cc:385] T c0d97839b0f24b7a8ee5a5877b8b2029: removed 2 log segments from log reader
I20260812 06:18:32.425021 27000 log.cc:1079] T c0d97839b0f24b7a8ee5a5877b8b2029 P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Deleting log segment in path: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515511783042-26815-0/minicluster-data/ts-0-root/wals/c0d97839b0f24b7a8ee5a5877b8b2029/wal-000000001 (ops 1-6)
I20260812 06:18:32.425098 27000 log.cc:1079] T c0d97839b0f24b7a8ee5a5877b8b2029 P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Deleting log segment in path: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515511783042-26815-0/minicluster-data/ts-0-root/wals/c0d97839b0f24b7a8ee5a5877b8b2029/wal-000000002 (ops 7-11)
I20260812 06:18:32.430051 27000 maintenance_manager.cc:643] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: LogGCOp(c0d97839b0f24b7a8ee5a5877b8b2029) complete. Timing: real 0.005s	user 0.000s	sys 0.005s Metrics: {}
I20260812 06:18:32.430737 27098 maintenance_manager.cc:419] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Scheduling FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029): perf score=2.188937
I20260812 06:18:32.465353 27000 maintenance_manager.cc:643] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029) complete. Timing: real 0.034s	user 0.009s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6027,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:32.466017 27098 maintenance_manager.cc:419] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Scheduling UndoDeltaBlockGCOp(c0d97839b0f24b7a8ee5a5877b8b2029): 16411393 bytes on disk
I20260812 06:18:32.466717 27000 maintenance_manager.cc:643] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: UndoDeltaBlockGCOp(c0d97839b0f24b7a8ee5a5877b8b2029) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":67,"lbm_reads_lt_1ms":4}
I20260812 06:18:32.467201 27098 maintenance_manager.cc:419] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Scheduling FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029): perf score=2.188937
I20260812 06:18:32.483925 27000 maintenance_manager.cc:643] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029) complete. Timing: real 0.016s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6278,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:32.484612 27098 maintenance_manager.cc:419] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Scheduling MajorDeltaCompactionOp(c0d97839b0f24b7a8ee5a5877b8b2029): perf score=1.000000
I20260812 06:18:32.668282 27000 maintenance_manager.cc:643] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: MajorDeltaCompactionOp(c0d97839b0f24b7a8ee5a5877b8b2029) complete. Timing: real 0.183s	user 0.111s	sys 0.072s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774808,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":621,"lbm_read_time_us":13252,"lbm_reads_lt_1ms":569,"lbm_write_time_us":31907,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":384,"thread_start_us":332,"threads_started":5,"update_count":2500}
I20260812 06:18:32.668973 27098 maintenance_manager.cc:419] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Scheduling FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029): perf score=10.126437
I20260812 06:18:32.717887 27000 maintenance_manager.cc:643] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029) complete. Timing: real 0.049s	user 0.033s	sys 0.007s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17237,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:32.718550 27098 maintenance_manager.cc:419] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Scheduling FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029): perf score=2.188937
I20260812 06:18:32.734511 27000 maintenance_manager.cc:643] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029) complete. Timing: real 0.016s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5786,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:32.735102 27098 maintenance_manager.cc:419] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Scheduling MajorDeltaCompactionOp(c0d97839b0f24b7a8ee5a5877b8b2029): perf score=1.000000
I20260812 06:18:32.879505 27000 maintenance_manager.cc:643] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: MajorDeltaCompactionOp(c0d97839b0f24b7a8ee5a5877b8b2029) complete. Timing: real 0.144s	user 0.097s	sys 0.035s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":658,"lbm_read_time_us":9722,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23963,"lbm_writes_lt_1ms":443,"mutex_wait_us":320,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8064,"update_count":2000}
I20260812 06:18:32.880214 27098 maintenance_manager.cc:419] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Scheduling FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029): perf score=10.126437
I20260812 06:18:32.925093 27000 maintenance_manager.cc:643] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029) complete. Timing: real 0.045s	user 0.027s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14877,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:32.925689 27098 maintenance_manager.cc:419] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Scheduling MajorDeltaCompactionOp(c0d97839b0f24b7a8ee5a5877b8b2029): perf score=1.000000
I20260812 06:18:33.038069 27000 maintenance_manager.cc:643] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: MajorDeltaCompactionOp(c0d97839b0f24b7a8ee5a5877b8b2029) complete. Timing: real 0.112s	user 0.083s	sys 0.029s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569746,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1253,"lbm_read_time_us":7632,"lbm_reads_lt_1ms":363,"lbm_write_time_us":18139,"lbm_writes_lt_1ms":343,"mutex_wait_us":354,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":39680,"update_count":1500}
I20260812 06:18:33.038806 27098 maintenance_manager.cc:419] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Scheduling FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029): perf score=10.126437
I20260812 06:18:33.076942 27000 maintenance_manager.cc:643] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029) complete. Timing: real 0.038s	user 0.014s	sys 0.021s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16193,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:33.077517 27098 maintenance_manager.cc:419] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Scheduling MajorDeltaCompactionOp(c0d97839b0f24b7a8ee5a5877b8b2029): perf score=1.000000
I20260812 06:18:33.200285 27000 maintenance_manager.cc:643] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: MajorDeltaCompactionOp(c0d97839b0f24b7a8ee5a5877b8b2029) complete. Timing: real 0.123s	user 0.098s	sys 0.025s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569746,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":182,"lbm_read_time_us":6659,"lbm_reads_lt_1ms":367,"lbm_write_time_us":20554,"lbm_writes_lt_1ms":343,"mutex_wait_us":47,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":7424,"update_count":1500}
I20260812 06:18:33.200989 27098 maintenance_manager.cc:419] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Scheduling FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029): perf score=10.126437
I20260812 06:18:33.240844 27000 maintenance_manager.cc:643] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029) complete. Timing: real 0.040s	user 0.030s	sys 0.007s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17545,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:33.241395 27098 maintenance_manager.cc:419] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Scheduling FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029): perf score=2.188937
I20260812 06:18:33.255313 27000 maintenance_manager.cc:643] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029) complete. Timing: real 0.014s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4908,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:33.255839 27098 maintenance_manager.cc:419] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Scheduling MajorDeltaCompactionOp(c0d97839b0f24b7a8ee5a5877b8b2029): perf score=1.000000
I20260812 06:18:33.393910 27000 maintenance_manager.cc:643] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: MajorDeltaCompactionOp(c0d97839b0f24b7a8ee5a5877b8b2029) complete. Timing: real 0.138s	user 0.097s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1368,"lbm_read_time_us":8786,"lbm_reads_lt_1ms":464,"lbm_write_time_us":28954,"lbm_writes_lt_1ms":443,"mutex_wait_us":554,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8320,"update_count":2000}
I20260812 06:18:33.394570 27098 maintenance_manager.cc:419] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Scheduling FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029): perf score=10.126437
I20260812 06:18:33.443872 27000 maintenance_manager.cc:643] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029) complete. Timing: real 0.049s	user 0.014s	sys 0.024s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17891,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:33.444458 27098 maintenance_manager.cc:419] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Scheduling FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029): perf score=2.188937
I20260812 06:18:33.457300 27000 maintenance_manager.cc:643] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029) complete. Timing: real 0.013s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102660,"delete_count":0,"lbm_write_time_us":4551,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:33.457897 27098 maintenance_manager.cc:419] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Scheduling MajorDeltaCompactionOp(c0d97839b0f24b7a8ee5a5877b8b2029): perf score=1.000000
I20260812 06:18:33.599160 27000 maintenance_manager.cc:643] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: MajorDeltaCompactionOp(c0d97839b0f24b7a8ee5a5877b8b2029) complete. Timing: real 0.141s	user 0.108s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":827,"lbm_read_time_us":10721,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27386,"lbm_writes_lt_1ms":443,"mutex_wait_us":25,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10880,"update_count":2000}
I20260812 06:18:33.599828 27098 maintenance_manager.cc:419] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Scheduling FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029): perf score=10.126437
I20260812 06:18:33.649274 27000 maintenance_manager.cc:643] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029) complete. Timing: real 0.049s	user 0.017s	sys 0.026s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":17554,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":1500}
I20260812 06:18:33.649973 27098 maintenance_manager.cc:419] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Scheduling FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029): perf score=2.188937
I20260812 06:18:33.661469 27000 maintenance_manager.cc:643] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4478,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:33.662029 27098 maintenance_manager.cc:419] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Scheduling MajorDeltaCompactionOp(c0d97839b0f24b7a8ee5a5877b8b2029): perf score=1.000000
I20260812 06:18:33.806682 27000 maintenance_manager.cc:643] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: MajorDeltaCompactionOp(c0d97839b0f24b7a8ee5a5877b8b2029) complete. Timing: real 0.144s	user 0.102s	sys 0.042s 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":65,"lbm_read_time_us":11604,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22441,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":2000}
I20260812 06:18:33.807863 27098 maintenance_manager.cc:419] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Scheduling FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029): perf score=10.126437
I20260812 06:18:33.839891 27000 maintenance_manager.cc:643] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029) complete. Timing: real 0.032s	user 0.013s	sys 0.016s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":13892,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:33.840484 27098 maintenance_manager.cc:419] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Scheduling FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029): perf score=2.188937
I20260812 06:18:33.858247 27000 maintenance_manager.cc:643] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029) complete. Timing: real 0.018s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5743,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:33.858728 27098 maintenance_manager.cc:419] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Scheduling FlushMRSOp(c0d97839b0f24b7a8ee5a5877b8b2029): perf score=1.000000
I20260812 06:18:33.910527 27000 maintenance_manager.cc:643] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: FlushMRSOp(c0d97839b0f24b7a8ee5a5877b8b2029) complete. Timing: real 0.052s	user 0.026s	sys 0.005s Metrics: {"bytes_written":1316413,"cfile_init":1,"dirs.queue_time_us":59,"dirs.run_cpu_time_us":238,"dirs.run_wall_time_us":1293,"drs_written":1,"lbm_read_time_us":42,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2125,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:18:33.911542 27098 maintenance_manager.cc:419] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Scheduling LogGCOp(c0d97839b0f24b7a8ee5a5877b8b2029): free 124257240 bytes of WAL
I20260812 06:18:33.911820 27000 log_reader.cc:385] T c0d97839b0f24b7a8ee5a5877b8b2029: removed 12 log segments from log reader
I20260812 06:18:33.911886 27000 log.cc:1079] T c0d97839b0f24b7a8ee5a5877b8b2029 P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Deleting log segment in path: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515511783042-26815-0/minicluster-data/ts-0-root/wals/c0d97839b0f24b7a8ee5a5877b8b2029/wal-000000003 (ops 12-16)
I20260812 06:18:33.911952 27000 log.cc:1079] T c0d97839b0f24b7a8ee5a5877b8b2029 P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Deleting log segment in path: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515511783042-26815-0/minicluster-data/ts-0-root/wals/c0d97839b0f24b7a8ee5a5877b8b2029/wal-000000004 (ops 17-21)
I20260812 06:18:33.912003 27000 log.cc:1079] T c0d97839b0f24b7a8ee5a5877b8b2029 P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Deleting log segment in path: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515511783042-26815-0/minicluster-data/ts-0-root/wals/c0d97839b0f24b7a8ee5a5877b8b2029/wal-000000005 (ops 22-26)
I20260812 06:18:33.912045 27000 log.cc:1079] T c0d97839b0f24b7a8ee5a5877b8b2029 P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Deleting log segment in path: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515511783042-26815-0/minicluster-data/ts-0-root/wals/c0d97839b0f24b7a8ee5a5877b8b2029/wal-000000006 (ops 27-31)
I20260812 06:18:33.912075 27000 log.cc:1079] T c0d97839b0f24b7a8ee5a5877b8b2029 P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Deleting log segment in path: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515511783042-26815-0/minicluster-data/ts-0-root/wals/c0d97839b0f24b7a8ee5a5877b8b2029/wal-000000007 (ops 32-36)
I20260812 06:18:33.912117 27000 log.cc:1079] T c0d97839b0f24b7a8ee5a5877b8b2029 P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Deleting log segment in path: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515511783042-26815-0/minicluster-data/ts-0-root/wals/c0d97839b0f24b7a8ee5a5877b8b2029/wal-000000008 (ops 37-40)
I20260812 06:18:33.912154 27000 log.cc:1079] T c0d97839b0f24b7a8ee5a5877b8b2029 P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Deleting log segment in path: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515511783042-26815-0/minicluster-data/ts-0-root/wals/c0d97839b0f24b7a8ee5a5877b8b2029/wal-000000009 (ops 41-45)
I20260812 06:18:33.912190 27000 log.cc:1079] T c0d97839b0f24b7a8ee5a5877b8b2029 P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Deleting log segment in path: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515511783042-26815-0/minicluster-data/ts-0-root/wals/c0d97839b0f24b7a8ee5a5877b8b2029/wal-000000010 (ops 46-50)
I20260812 06:18:33.912226 27000 log.cc:1079] T c0d97839b0f24b7a8ee5a5877b8b2029 P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Deleting log segment in path: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515511783042-26815-0/minicluster-data/ts-0-root/wals/c0d97839b0f24b7a8ee5a5877b8b2029/wal-000000011 (ops 51-55)
I20260812 06:18:33.912264 27000 log.cc:1079] T c0d97839b0f24b7a8ee5a5877b8b2029 P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Deleting log segment in path: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515511783042-26815-0/minicluster-data/ts-0-root/wals/c0d97839b0f24b7a8ee5a5877b8b2029/wal-000000012 (ops 56-60)
I20260812 06:18:33.912299 27000 log.cc:1079] T c0d97839b0f24b7a8ee5a5877b8b2029 P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Deleting log segment in path: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515511783042-26815-0/minicluster-data/ts-0-root/wals/c0d97839b0f24b7a8ee5a5877b8b2029/wal-000000013 (ops 61-65)
I20260812 06:18:33.912336 27000 log.cc:1079] T c0d97839b0f24b7a8ee5a5877b8b2029 P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Deleting log segment in path: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515511783042-26815-0/minicluster-data/ts-0-root/wals/c0d97839b0f24b7a8ee5a5877b8b2029/wal-000000014 (ops 66-70)
I20260812 06:18:33.938910 27000 maintenance_manager.cc:643] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: LogGCOp(c0d97839b0f24b7a8ee5a5877b8b2029) complete. Timing: real 0.027s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:18:33.943502 27098 maintenance_manager.cc:419] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Scheduling UndoDeltaBlockGCOp(c0d97839b0f24b7a8ee5a5877b8b2029): 493 bytes on disk
I20260812 06:18:33.944000 27000 maintenance_manager.cc:643] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: UndoDeltaBlockGCOp(c0d97839b0f24b7a8ee5a5877b8b2029) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4}
I20260812 06:18:33.944494 27098 maintenance_manager.cc:419] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Scheduling FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029): perf score=6.157687
I20260812 06:18:33.963734 27000 maintenance_manager.cc:643] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029) complete. Timing: real 0.019s	user 0.000s	sys 0.017s Metrics: {"bytes_written":8205079,"delete_count":0,"lbm_write_time_us":8359,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:18:33.964248 27098 maintenance_manager.cc:419] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Scheduling LogGCOp(c0d97839b0f24b7a8ee5a5877b8b2029): free 8767118 bytes of WAL
I20260812 06:18:33.964453 27000 log_reader.cc:385] T c0d97839b0f24b7a8ee5a5877b8b2029: removed 1 log segments from log reader
I20260812 06:18:33.964495 27000 log.cc:1079] T c0d97839b0f24b7a8ee5a5877b8b2029 P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Deleting log segment in path: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515511783042-26815-0/minicluster-data/ts-0-root/wals/c0d97839b0f24b7a8ee5a5877b8b2029/wal-000000015 (ops 71-75)
I20260812 06:18:33.966477 27000 maintenance_manager.cc:643] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: LogGCOp(c0d97839b0f24b7a8ee5a5877b8b2029) complete. Timing: real 0.002s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:18:33.966814 27098 maintenance_manager.cc:419] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Scheduling FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029): perf score=2.188937
I20260812 06:18:33.979166 27000 maintenance_manager.cc:643] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029) complete. Timing: real 0.012s	user 0.001s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4192,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:33.979715 27098 maintenance_manager.cc:419] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Scheduling MajorDeltaCompactionOp(c0d97839b0f24b7a8ee5a5877b8b2029): perf score=1.000000
I20260812 06:18:34.210400 27000 maintenance_manager.cc:643] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: MajorDeltaCompactionOp(c0d97839b0f24b7a8ee5a5877b8b2029) complete. Timing: real 0.230s	user 0.127s	sys 0.100s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979754,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":656,"lbm_read_time_us":16429,"lbm_reads_lt_1ms":774,"lbm_write_time_us":40747,"lbm_writes_lt_1ms":743,"mutex_wait_us":612,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":12160,"thread_start_us":90,"threads_started":1,"update_count":3500}
I20260812 06:18:34.211663 27098 maintenance_manager.cc:419] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Scheduling FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029): perf score=17.071750
I20260812 06:18:34.284368 27000 maintenance_manager.cc:643] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029) complete. Timing: real 0.073s	user 0.029s	sys 0.032s Metrics: {"bytes_written":18666228,"delete_count":0,"lbm_write_time_us":26535,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":457,"reinsert_count":0,"update_count":2275}
I20260812 06:18:34.284917 27098 maintenance_manager.cc:419] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Scheduling FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029): perf score=4.173312
I20260812 06:18:34.306562 27000 maintenance_manager.cc:643] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029) complete. Timing: real 0.021s	user 0.017s	sys 0.004s Metrics: {"bytes_written":5948759,"delete_count":0,"lbm_write_time_us":8688,"lbm_writes_lt_1ms":148,"reinsert_count":0,"update_count":725}
I20260812 06:18:34.307077 27098 maintenance_manager.cc:419] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Scheduling MajorDeltaCompactionOp(c0d97839b0f24b7a8ee5a5877b8b2029): perf score=1.000000
I20260812 06:18:34.502272 27000 maintenance_manager.cc:643] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: MajorDeltaCompactionOp(c0d97839b0f24b7a8ee5a5877b8b2029) complete. Timing: real 0.195s	user 0.132s	sys 0.063s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877109,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":374,"lbm_read_time_us":12569,"lbm_reads_lt_1ms":664,"lbm_write_time_us":33029,"lbm_writes_lt_1ms":643,"mutex_wait_us":113,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:18:34.503057 27098 maintenance_manager.cc:419] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Scheduling FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029): perf score=14.095187
I20260812 06:18:34.557031 27000 maintenance_manager.cc:643] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029) complete. Timing: real 0.054s	user 0.010s	sys 0.040s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":23687,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:34.557703 27098 maintenance_manager.cc:419] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Scheduling FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029): perf score=2.188937
I20260812 06:18:34.570129 27000 maintenance_manager.cc:643] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029) complete. Timing: real 0.012s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4905,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:34.570679 27098 maintenance_manager.cc:419] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Scheduling MajorDeltaCompactionOp(c0d97839b0f24b7a8ee5a5877b8b2029): perf score=1.000000
I20260812 06:18:34.736768 27000 maintenance_manager.cc:643] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: MajorDeltaCompactionOp(c0d97839b0f24b7a8ee5a5877b8b2029) complete. Timing: real 0.166s	user 0.116s	sys 0.049s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":188,"lbm_read_time_us":11757,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28120,"lbm_writes_lt_1ms":543,"mutex_wait_us":58,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7040,"update_count":2500}
I20260812 06:18:34.737443 27098 maintenance_manager.cc:419] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Scheduling FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029): perf score=14.095187
I20260812 06:18:34.792513 27000 maintenance_manager.cc:643] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029) complete. Timing: real 0.055s	user 0.021s	sys 0.022s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19115,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:34.793092 27098 maintenance_manager.cc:419] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Scheduling FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029): perf score=2.188937
I20260812 06:18:34.804774 27000 maintenance_manager.cc:643] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4175,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:34.805368 27098 maintenance_manager.cc:419] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Scheduling MajorDeltaCompactionOp(c0d97839b0f24b7a8ee5a5877b8b2029): perf score=1.000000
I20260812 06:18:34.980746 27000 maintenance_manager.cc:643] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: MajorDeltaCompactionOp(c0d97839b0f24b7a8ee5a5877b8b2029) complete. Timing: real 0.175s	user 0.118s	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":178,"lbm_read_time_us":13790,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28143,"lbm_writes_lt_1ms":543,"mutex_wait_us":43,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":16512,"update_count":2500}
I20260812 06:18:34.981446 27098 maintenance_manager.cc:419] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Scheduling FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029): perf score=14.095187
I20260812 06:18:35.035780 27000 maintenance_manager.cc:643] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029) complete. Timing: real 0.054s	user 0.040s	sys 0.012s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19633,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:35.036351 27098 maintenance_manager.cc:419] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Scheduling FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029): perf score=2.188937
I20260812 06:18:35.046993 27000 maintenance_manager.cc:643] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4014,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:35.047616 27098 maintenance_manager.cc:419] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Scheduling MajorDeltaCompactionOp(c0d97839b0f24b7a8ee5a5877b8b2029): perf score=1.000000
I20260812 06:18:35.230706 27000 maintenance_manager.cc:643] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: MajorDeltaCompactionOp(c0d97839b0f24b7a8ee5a5877b8b2029) complete. Timing: real 0.183s	user 0.129s	sys 0.050s 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":283,"lbm_read_time_us":11886,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30359,"lbm_writes_lt_1ms":543,"mutex_wait_us":2,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:35.231559 27098 maintenance_manager.cc:419] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Scheduling FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029): perf score=14.095187
I20260812 06:18:35.308566 27000 maintenance_manager.cc:643] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029) complete. Timing: real 0.077s	user 0.029s	sys 0.036s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":26491,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:35.309468 27098 maintenance_manager.cc:419] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Scheduling FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029): perf score=2.188937
I20260812 06:18:35.327814 27000 maintenance_manager.cc:643] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029) complete. Timing: real 0.018s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6669,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:35.329862 27098 maintenance_manager.cc:419] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Scheduling FlushMRSOp(c0d97839b0f24b7a8ee5a5877b8b2029): perf score=1.000000
I20260812 06:18:35.367345 27000 maintenance_manager.cc:643] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: FlushMRSOp(c0d97839b0f24b7a8ee5a5877b8b2029) complete. Timing: real 0.037s	user 0.024s	sys 0.004s Metrics: {"bytes_written":1152512,"cfile_init":1,"dirs.queue_time_us":78,"dirs.run_cpu_time_us":198,"dirs.run_wall_time_us":1221,"drs_written":1,"lbm_read_time_us":45,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1539,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:35.368176 27098 maintenance_manager.cc:419] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Scheduling LogGCOp(c0d97839b0f24b7a8ee5a5877b8b2029): free 108535463 bytes of WAL
I20260812 06:18:35.368423 27000 log_reader.cc:385] T c0d97839b0f24b7a8ee5a5877b8b2029: removed 11 log segments from log reader
I20260812 06:18:35.368471 27000 log.cc:1079] T c0d97839b0f24b7a8ee5a5877b8b2029 P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Deleting log segment in path: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515511783042-26815-0/minicluster-data/ts-0-root/wals/c0d97839b0f24b7a8ee5a5877b8b2029/wal-000000016 (ops 76-80)
I20260812 06:18:35.368538 27000 log.cc:1079] T c0d97839b0f24b7a8ee5a5877b8b2029 P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Deleting log segment in path: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515511783042-26815-0/minicluster-data/ts-0-root/wals/c0d97839b0f24b7a8ee5a5877b8b2029/wal-000000017 (ops 81-85)
I20260812 06:18:35.368584 27000 log.cc:1079] T c0d97839b0f24b7a8ee5a5877b8b2029 P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Deleting log segment in path: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515511783042-26815-0/minicluster-data/ts-0-root/wals/c0d97839b0f24b7a8ee5a5877b8b2029/wal-000000018 (ops 86-90)
I20260812 06:18:35.368649 27000 log.cc:1079] T c0d97839b0f24b7a8ee5a5877b8b2029 P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Deleting log segment in path: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515511783042-26815-0/minicluster-data/ts-0-root/wals/c0d97839b0f24b7a8ee5a5877b8b2029/wal-000000019 (ops 91-94)
I20260812 06:18:35.368693 27000 log.cc:1079] T c0d97839b0f24b7a8ee5a5877b8b2029 P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Deleting log segment in path: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515511783042-26815-0/minicluster-data/ts-0-root/wals/c0d97839b0f24b7a8ee5a5877b8b2029/wal-000000020 (ops 95-99)
I20260812 06:18:35.368746 27000 log.cc:1079] T c0d97839b0f24b7a8ee5a5877b8b2029 P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Deleting log segment in path: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515511783042-26815-0/minicluster-data/ts-0-root/wals/c0d97839b0f24b7a8ee5a5877b8b2029/wal-000000021 (ops 100-104)
I20260812 06:18:35.368789 27000 log.cc:1079] T c0d97839b0f24b7a8ee5a5877b8b2029 P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Deleting log segment in path: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515511783042-26815-0/minicluster-data/ts-0-root/wals/c0d97839b0f24b7a8ee5a5877b8b2029/wal-000000022 (ops 105-108)
I20260812 06:18:35.368830 27000 log.cc:1079] T c0d97839b0f24b7a8ee5a5877b8b2029 P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Deleting log segment in path: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515511783042-26815-0/minicluster-data/ts-0-root/wals/c0d97839b0f24b7a8ee5a5877b8b2029/wal-000000023 (ops 109-113)
I20260812 06:18:35.368871 27000 log.cc:1079] T c0d97839b0f24b7a8ee5a5877b8b2029 P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Deleting log segment in path: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515511783042-26815-0/minicluster-data/ts-0-root/wals/c0d97839b0f24b7a8ee5a5877b8b2029/wal-000000024 (ops 114-118)
I20260812 06:18:35.368911 27000 log.cc:1079] T c0d97839b0f24b7a8ee5a5877b8b2029 P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Deleting log segment in path: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515511783042-26815-0/minicluster-data/ts-0-root/wals/c0d97839b0f24b7a8ee5a5877b8b2029/wal-000000025 (ops 119-123)
I20260812 06:18:35.368950 27000 log.cc:1079] T c0d97839b0f24b7a8ee5a5877b8b2029 P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Deleting log segment in path: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515511783042-26815-0/minicluster-data/ts-0-root/wals/c0d97839b0f24b7a8ee5a5877b8b2029/wal-000000026 (ops 124-128)
I20260812 06:18:35.393256 27000 maintenance_manager.cc:643] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: LogGCOp(c0d97839b0f24b7a8ee5a5877b8b2029) complete. Timing: real 0.025s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:18:35.393978 27098 maintenance_manager.cc:419] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Scheduling FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029): perf score=3.181125
I20260812 06:18:35.416133 27000 maintenance_manager.cc:643] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029) complete. Timing: real 0.022s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4307783,"delete_count":0,"lbm_write_time_us":6948,"lbm_writes_lt_1ms":108,"reinsert_count":0,"update_count":525}
I20260812 06:18:35.416622 27098 maintenance_manager.cc:419] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Scheduling FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029): perf score=2.188937
I20260812 06:18:35.427052 27000 maintenance_manager.cc:643] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3897534,"delete_count":0,"lbm_write_time_us":3922,"lbm_writes_lt_1ms":98,"reinsert_count":0,"update_count":475}
I20260812 06:18:35.427582 27098 maintenance_manager.cc:419] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Scheduling UndoDeltaBlockGCOp(c0d97839b0f24b7a8ee5a5877b8b2029): 447 bytes on disk
I20260812 06:18:35.428030 27000 maintenance_manager.cc:643] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: UndoDeltaBlockGCOp(c0d97839b0f24b7a8ee5a5877b8b2029) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4}
I20260812 06:18:35.428731 27098 maintenance_manager.cc:419] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Scheduling MajorDeltaCompactionOp(c0d97839b0f24b7a8ee5a5877b8b2029): perf score=1.000000
I20260812 06:18:35.664438 27000 maintenance_manager.cc:643] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: MajorDeltaCompactionOp(c0d97839b0f24b7a8ee5a5877b8b2029) complete. Timing: real 0.236s	user 0.159s	sys 0.071s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979749,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1377,"lbm_read_time_us":15757,"lbm_reads_lt_1ms":774,"lbm_write_time_us":37114,"lbm_writes_lt_1ms":743,"mutex_wait_us":369,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":15104,"thread_start_us":85,"threads_started":1,"update_count":3500}
I20260812 06:18:35.665277 27098 maintenance_manager.cc:419] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Scheduling FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029): perf score=18.063937
I20260812 06:18:35.733510 27000 maintenance_manager.cc:643] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029) complete. Timing: real 0.068s	user 0.032s	sys 0.024s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":27384,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":501,"reinsert_count":0,"update_count":2500}
I20260812 06:18:35.734176 27098 maintenance_manager.cc:419] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Scheduling FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029): perf score=2.188937
I20260812 06:18:35.750072 27000 maintenance_manager.cc:643] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029) complete. Timing: real 0.016s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5824,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:35.750761 27098 maintenance_manager.cc:419] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Scheduling MajorDeltaCompactionOp(c0d97839b0f24b7a8ee5a5877b8b2029): perf score=1.000000
I20260812 06:18:35.946319 27000 maintenance_manager.cc:643] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: MajorDeltaCompactionOp(c0d97839b0f24b7a8ee5a5877b8b2029) complete. Timing: real 0.195s	user 0.128s	sys 0.063s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877104,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":412,"lbm_read_time_us":11387,"lbm_reads_lt_1ms":672,"lbm_write_time_us":34690,"lbm_writes_lt_1ms":643,"mutex_wait_us":84,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":3000}
I20260812 06:18:35.947141 27098 maintenance_manager.cc:419] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Scheduling FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029): perf score=16.079562
I20260812 06:18:36.009454 27000 maintenance_manager.cc:643] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029) complete. Timing: real 0.062s	user 0.032s	sys 0.020s Metrics: {"bytes_written":17804723,"delete_count":0,"lbm_write_time_us":27223,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":434,"reinsert_count":0,"update_count":2170}
I20260812 06:18:36.010006 27098 maintenance_manager.cc:419] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Scheduling FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029): perf score=5.165500
I20260812 06:18:36.027707 27000 maintenance_manager.cc:643] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029) complete. Timing: real 0.018s	user 0.014s	sys 0.001s Metrics: {"bytes_written":6810264,"delete_count":0,"lbm_write_time_us":7049,"lbm_writes_lt_1ms":169,"reinsert_count":0,"update_count":830}
I20260812 06:18:36.028206 27098 maintenance_manager.cc:419] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Scheduling MajorDeltaCompactionOp(c0d97839b0f24b7a8ee5a5877b8b2029): perf score=1.000000
I20260812 06:18:36.241146 27000 maintenance_manager.cc:643] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: MajorDeltaCompactionOp(c0d97839b0f24b7a8ee5a5877b8b2029) complete. Timing: real 0.213s	user 0.109s	sys 0.094s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877109,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":804,"lbm_read_time_us":13908,"lbm_reads_lt_1ms":668,"lbm_write_time_us":35801,"lbm_writes_lt_1ms":643,"mutex_wait_us":55,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":13056,"update_count":3000}
I20260812 06:18:36.241830 27098 maintenance_manager.cc:419] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Scheduling FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029): perf score=18.063937
I20260812 06:18:36.293329 27000 maintenance_manager.cc:643] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029) complete. Timing: real 0.051s	user 0.019s	sys 0.028s Metrics: {"bytes_written":20512318,"delete_count":0,"lbm_write_time_us":23331,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:36.293846 27098 maintenance_manager.cc:419] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Scheduling MajorDeltaCompactionOp(c0d97839b0f24b7a8ee5a5877b8b2029): perf score=1.000000
I20260812 06:18:36.462226 27000 maintenance_manager.cc:643] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: MajorDeltaCompactionOp(c0d97839b0f24b7a8ee5a5877b8b2029) complete. Timing: real 0.168s	user 0.127s	sys 0.040s Metrics: {"cfile_cache_miss":531,"cfile_cache_miss_bytes":24774574,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":740,"lbm_read_time_us":11755,"lbm_reads_lt_1ms":563,"lbm_write_time_us":29173,"lbm_writes_lt_1ms":543,"mutex_wait_us":81,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:36.462963 27098 maintenance_manager.cc:419] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Scheduling FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029): perf score=14.095187
I20260812 06:18:36.524833 27000 maintenance_manager.cc:643] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029) complete. Timing: real 0.062s	user 0.035s	sys 0.023s Metrics: {"bytes_written":16409899,"delete_count":0,"lbm_write_time_us":24707,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:36.525436 27098 maintenance_manager.cc:419] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Scheduling FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029): perf score=2.188937
I20260812 06:18:36.535980 27000 maintenance_manager.cc:643] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3958,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:36.536448 27098 maintenance_manager.cc:419] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Scheduling MajorDeltaCompactionOp(c0d97839b0f24b7a8ee5a5877b8b2029): perf score=1.000000
I20260812 06:18:36.719839 27000 maintenance_manager.cc:643] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: MajorDeltaCompactionOp(c0d97839b0f24b7a8ee5a5877b8b2029) complete. Timing: real 0.183s	user 0.116s	sys 0.053s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":267,"lbm_read_time_us":12770,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30310,"lbm_writes_lt_1ms":543,"mutex_wait_us":2,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2500}
I20260812 06:18:36.720587 27098 maintenance_manager.cc:419] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Scheduling FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029): perf score=14.095187
I20260812 06:18:36.790387 27000 maintenance_manager.cc:643] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029) complete. Timing: real 0.070s	user 0.030s	sys 0.031s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":23684,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:36.790969 27098 maintenance_manager.cc:419] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Scheduling FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029): perf score=2.188937
I20260812 06:18:36.801921 27000 maintenance_manager.cc:643] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4102,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:36.802448 27098 maintenance_manager.cc:419] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Scheduling FlushMRSOp(c0d97839b0f24b7a8ee5a5877b8b2029): perf score=1.000000
I20260812 06:18:36.845778 27000 maintenance_manager.cc:643] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: FlushMRSOp(c0d97839b0f24b7a8ee5a5877b8b2029) complete. Timing: real 0.043s	user 0.027s	sys 0.003s Metrics: {"bytes_written":1193507,"cfile_init":1,"dirs.queue_time_us":67,"dirs.run_cpu_time_us":217,"dirs.run_wall_time_us":1263,"drs_written":1,"lbm_read_time_us":43,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1381,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:36.846707 27098 maintenance_manager.cc:419] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Scheduling LogGCOp(c0d97839b0f24b7a8ee5a5877b8b2029): free 123804460 bytes of WAL
I20260812 06:18:36.846946 27000 log_reader.cc:385] T c0d97839b0f24b7a8ee5a5877b8b2029: removed 12 log segments from log reader
I20260812 06:18:36.846993 27000 log.cc:1079] T c0d97839b0f24b7a8ee5a5877b8b2029 P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Deleting log segment in path: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515511783042-26815-0/minicluster-data/ts-0-root/wals/c0d97839b0f24b7a8ee5a5877b8b2029/wal-000000027 (ops 129-133)
I20260812 06:18:36.847021 27000 log.cc:1079] T c0d97839b0f24b7a8ee5a5877b8b2029 P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Deleting log segment in path: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515511783042-26815-0/minicluster-data/ts-0-root/wals/c0d97839b0f24b7a8ee5a5877b8b2029/wal-000000028 (ops 134-138)
I20260812 06:18:36.847087 27000 log.cc:1079] T c0d97839b0f24b7a8ee5a5877b8b2029 P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Deleting log segment in path: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515511783042-26815-0/minicluster-data/ts-0-root/wals/c0d97839b0f24b7a8ee5a5877b8b2029/wal-000000029 (ops 139-143)
I20260812 06:18:36.847127 27000 log.cc:1079] T c0d97839b0f24b7a8ee5a5877b8b2029 P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Deleting log segment in path: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515511783042-26815-0/minicluster-data/ts-0-root/wals/c0d97839b0f24b7a8ee5a5877b8b2029/wal-000000030 (ops 144-148)
I20260812 06:18:36.847167 27000 log.cc:1079] T c0d97839b0f24b7a8ee5a5877b8b2029 P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Deleting log segment in path: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515511783042-26815-0/minicluster-data/ts-0-root/wals/c0d97839b0f24b7a8ee5a5877b8b2029/wal-000000031 (ops 149-153)
I20260812 06:18:36.847206 27000 log.cc:1079] T c0d97839b0f24b7a8ee5a5877b8b2029 P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Deleting log segment in path: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515511783042-26815-0/minicluster-data/ts-0-root/wals/c0d97839b0f24b7a8ee5a5877b8b2029/wal-000000032 (ops 154-158)
I20260812 06:18:36.847249 27000 log.cc:1079] T c0d97839b0f24b7a8ee5a5877b8b2029 P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Deleting log segment in path: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515511783042-26815-0/minicluster-data/ts-0-root/wals/c0d97839b0f24b7a8ee5a5877b8b2029/wal-000000033 (ops 159-162)
I20260812 06:18:36.847289 27000 log.cc:1079] T c0d97839b0f24b7a8ee5a5877b8b2029 P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Deleting log segment in path: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515511783042-26815-0/minicluster-data/ts-0-root/wals/c0d97839b0f24b7a8ee5a5877b8b2029/wal-000000034 (ops 163-167)
I20260812 06:18:36.847328 27000 log.cc:1079] T c0d97839b0f24b7a8ee5a5877b8b2029 P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Deleting log segment in path: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515511783042-26815-0/minicluster-data/ts-0-root/wals/c0d97839b0f24b7a8ee5a5877b8b2029/wal-000000035 (ops 168-172)
I20260812 06:18:36.847368 27000 log.cc:1079] T c0d97839b0f24b7a8ee5a5877b8b2029 P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Deleting log segment in path: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515511783042-26815-0/minicluster-data/ts-0-root/wals/c0d97839b0f24b7a8ee5a5877b8b2029/wal-000000036 (ops 173-176)
I20260812 06:18:36.847406 27000 log.cc:1079] T c0d97839b0f24b7a8ee5a5877b8b2029 P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Deleting log segment in path: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515511783042-26815-0/minicluster-data/ts-0-root/wals/c0d97839b0f24b7a8ee5a5877b8b2029/wal-000000037 (ops 177-181)
I20260812 06:18:36.847445 27000 log.cc:1079] T c0d97839b0f24b7a8ee5a5877b8b2029 P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Deleting log segment in path: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515511783042-26815-0/minicluster-data/ts-0-root/wals/c0d97839b0f24b7a8ee5a5877b8b2029/wal-000000038 (ops 182-186)
I20260812 06:18:36.873517 27000 maintenance_manager.cc:643] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: LogGCOp(c0d97839b0f24b7a8ee5a5877b8b2029) complete. Timing: real 0.027s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:18:36.874028 27098 maintenance_manager.cc:419] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Scheduling UndoDeltaBlockGCOp(c0d97839b0f24b7a8ee5a5877b8b2029): 463 bytes on disk
I20260812 06:18:36.874495 27000 maintenance_manager.cc:643] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: UndoDeltaBlockGCOp(c0d97839b0f24b7a8ee5a5877b8b2029) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4}
I20260812 06:18:36.875058 27098 maintenance_manager.cc:419] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Scheduling FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029): perf score=2.188937
I20260812 06:18:36.892632 27000 maintenance_manager.cc:643] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029) complete. Timing: real 0.017s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4143684,"delete_count":0,"lbm_write_time_us":4045,"lbm_writes_lt_1ms":104,"reinsert_count":0,"update_count":505}
I20260812 06:18:36.893203 27098 maintenance_manager.cc:419] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Scheduling FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029): perf score=2.188937
I20260812 06:18:36.903541 27000 maintenance_manager.cc:643] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029) complete. Timing: real 0.010s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4061633,"delete_count":0,"lbm_write_time_us":3827,"lbm_writes_lt_1ms":102,"reinsert_count":0,"update_count":495}
I20260812 06:18:36.904198 27098 maintenance_manager.cc:419] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Scheduling MajorDeltaCompactionOp(c0d97839b0f24b7a8ee5a5877b8b2029): perf score=1.000000
I20260812 06:18:37.151027 26815 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.060s	user 1.857s	sys 0.187s
I20260812 06:18:37.166005 27000 maintenance_manager.cc:643] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: MajorDeltaCompactionOp(c0d97839b0f24b7a8ee5a5877b8b2029) complete. Timing: real 0.262s	user 0.174s	sys 0.077s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979753,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1393,"lbm_read_time_us":16437,"lbm_reads_lt_1ms":774,"lbm_write_time_us":44166,"lbm_writes_lt_1ms":743,"mutex_wait_us":403,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":76544,"thread_start_us":88,"threads_started":1,"update_count":3500}
I20260812 06:18:37.166838 27098 maintenance_manager.cc:419] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: Scheduling FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029): perf score=18.063937
I20260812 06:18:37.208302 26815 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.057s	user 0.002s	sys 0.000s
I20260812 06:18:37.209048 26815 tablet_server.cc:179] TabletServer@127.26.47.193:0 shutting down...
I20260812 06:18:37.223953 27000 maintenance_manager.cc:643] P 4e070d2fb6f8495fb5d07d3dd69d4b9e: FlushDeltaMemStoresOp(c0d97839b0f24b7a8ee5a5877b8b2029) complete. Timing: real 0.057s	user 0.030s	sys 0.024s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":25799,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:37.224556 26815 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:37.224951 26815 tablet_replica.cc:333] T c0d97839b0f24b7a8ee5a5877b8b2029 P 4e070d2fb6f8495fb5d07d3dd69d4b9e: stopping tablet replica
I20260812 06:18:37.225200 26815 raft_consensus.cc:2243] T c0d97839b0f24b7a8ee5a5877b8b2029 P 4e070d2fb6f8495fb5d07d3dd69d4b9e [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:37.225438 26815 raft_consensus.cc:2272] T c0d97839b0f24b7a8ee5a5877b8b2029 P 4e070d2fb6f8495fb5d07d3dd69d4b9e [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:37.230353 26815 tablet_server.cc:196] TabletServer@127.26.47.193:0 shutdown complete.
I20260812 06:18:37.234804 26815 master.cc:562] Master@127.26.47.254:42419 shutting down...
I20260812 06:18:37.238309 26815 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 968c93097add4f36af1583ef86391d58 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:37.238497 26815 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 968c93097add4f36af1583ef86391d58 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:37.238598 26815 tablet_replica.cc:333] T 00000000000000000000000000000000 P 968c93097add4f36af1583ef86391d58: stopping tablet replica
I20260812 06:18:37.250864 26815 master.cc:584] Master@127.26.47.254:42419 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5547 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:37.340540 26815 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.26.47.254:46581
I20260812 06:18:37.340963 26815 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:37.343444 27148 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:37.343518 26815 server_base.cc:1061] running on GCE node
W20260812 06:18:37.343513 27153 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:37.343600 27150 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:37.343892 26815 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:37.343940 26815 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:37.343954 26815 hybrid_clock.cc:648] HybridClock initialized: now 1786515517343954 us; error 0 us; skew 500 ppm
I20260812 06:18:37.344810 26815 webserver.cc:533] Webserver started at http://127.26.47.254:46603/ using document root <none> and password file <none>
I20260812 06:18:37.344944 26815 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:37.344986 26815 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:37.345043 26815 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:37.345395 26815 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515511783042-26815-0/minicluster-data/master-0-root/instance:
uuid: "451ed6a4da04412fa6de6c8eb102cc3d"
format_stamp: "Formatted at 2026-08-12 06:18:37 on dist-test-slave-gsp7"
I20260812 06:18:37.347010 26815 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:37.348055 27166 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:37.348307 26815 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:37.348409 26815 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515511783042-26815-0/minicluster-data/master-0-root
uuid: "451ed6a4da04412fa6de6c8eb102cc3d"
format_stamp: "Formatted at 2026-08-12 06:18:37 on dist-test-slave-gsp7"
I20260812 06:18:37.348501 26815 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515511783042-26815-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515511783042-26815-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515511783042-26815-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:37.369578 26815 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:37.370057 26815 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:37.374399 26815 rpc_server.cc:307] RPC server started. Bound to: 127.26.47.254:46581
I20260812 06:18:37.376538 27249 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.26.47.254:46581 every 8 connection(s)
I20260812 06:18:37.378346 27250 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:37.388080 27250 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 451ed6a4da04412fa6de6c8eb102cc3d: Bootstrap starting.
I20260812 06:18:37.388947 27250 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 451ed6a4da04412fa6de6c8eb102cc3d: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:37.390134 27250 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 451ed6a4da04412fa6de6c8eb102cc3d: No bootstrap required, opened a new log
I20260812 06:18:37.390517 27250 raft_consensus.cc:359] T 00000000000000000000000000000000 P 451ed6a4da04412fa6de6c8eb102cc3d [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "451ed6a4da04412fa6de6c8eb102cc3d" member_type: VOTER }
I20260812 06:18:37.390610 27250 raft_consensus.cc:385] T 00000000000000000000000000000000 P 451ed6a4da04412fa6de6c8eb102cc3d [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:37.390633 27250 raft_consensus.cc:740] T 00000000000000000000000000000000 P 451ed6a4da04412fa6de6c8eb102cc3d [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 451ed6a4da04412fa6de6c8eb102cc3d, State: Initialized, Role: FOLLOWER
I20260812 06:18:37.390789 27250 consensus_queue.cc:260] T 00000000000000000000000000000000 P 451ed6a4da04412fa6de6c8eb102cc3d [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: "451ed6a4da04412fa6de6c8eb102cc3d" member_type: VOTER }
I20260812 06:18:37.390892 27250 raft_consensus.cc:399] T 00000000000000000000000000000000 P 451ed6a4da04412fa6de6c8eb102cc3d [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:37.390918 27250 raft_consensus.cc:493] T 00000000000000000000000000000000 P 451ed6a4da04412fa6de6c8eb102cc3d [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:37.390954 27250 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 451ed6a4da04412fa6de6c8eb102cc3d [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:37.391661 27250 raft_consensus.cc:515] T 00000000000000000000000000000000 P 451ed6a4da04412fa6de6c8eb102cc3d [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "451ed6a4da04412fa6de6c8eb102cc3d" member_type: VOTER }
I20260812 06:18:37.391779 27250 leader_election.cc:304] T 00000000000000000000000000000000 P 451ed6a4da04412fa6de6c8eb102cc3d [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: 451ed6a4da04412fa6de6c8eb102cc3d; no voters: 
I20260812 06:18:37.391957 27250 leader_election.cc:290] T 00000000000000000000000000000000 P 451ed6a4da04412fa6de6c8eb102cc3d [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:37.392119 27255 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 451ed6a4da04412fa6de6c8eb102cc3d [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:37.392386 27255 raft_consensus.cc:697] T 00000000000000000000000000000000 P 451ed6a4da04412fa6de6c8eb102cc3d [term 1 LEADER]: Becoming Leader. State: Replica: 451ed6a4da04412fa6de6c8eb102cc3d, State: Running, Role: LEADER
I20260812 06:18:37.392503 27250 sys_catalog.cc:565] T 00000000000000000000000000000000 P 451ed6a4da04412fa6de6c8eb102cc3d [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:37.392588 27255 consensus_queue.cc:237] T 00000000000000000000000000000000 P 451ed6a4da04412fa6de6c8eb102cc3d [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: "451ed6a4da04412fa6de6c8eb102cc3d" member_type: VOTER }
I20260812 06:18:37.393033 27256 sys_catalog.cc:455] T 00000000000000000000000000000000 P 451ed6a4da04412fa6de6c8eb102cc3d [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "451ed6a4da04412fa6de6c8eb102cc3d" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "451ed6a4da04412fa6de6c8eb102cc3d" member_type: VOTER } }
I20260812 06:18:37.393143 27256 sys_catalog.cc:458] T 00000000000000000000000000000000 P 451ed6a4da04412fa6de6c8eb102cc3d [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:37.393052 27258 sys_catalog.cc:455] T 00000000000000000000000000000000 P 451ed6a4da04412fa6de6c8eb102cc3d [sys.catalog]: SysCatalogTable state changed. Reason: New leader 451ed6a4da04412fa6de6c8eb102cc3d. Latest consensus state: current_term: 1 leader_uuid: "451ed6a4da04412fa6de6c8eb102cc3d" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "451ed6a4da04412fa6de6c8eb102cc3d" member_type: VOTER } }
I20260812 06:18:37.393386 27258 sys_catalog.cc:458] T 00000000000000000000000000000000 P 451ed6a4da04412fa6de6c8eb102cc3d [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:37.393951 27266 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:37.394991 27266 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:37.395187 26815 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:37.396821 27266 catalog_manager.cc:1383] Generated new cluster ID: a4e8ead9ac92454d818b8300f9244f64
I20260812 06:18:37.396888 27266 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:37.416821 27266 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:37.417433 27266 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:37.428257 27266 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 451ed6a4da04412fa6de6c8eb102cc3d: Generated new TSK 0
I20260812 06:18:37.428481 27266 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:37.459865 26815 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:37.462070 27301 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:37.462075 27295 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:37.462044 27296 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:37.462299 26815 server_base.cc:1061] running on GCE node
I20260812 06:18:37.462584 26815 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:37.462651 26815 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:37.462677 26815 hybrid_clock.cc:648] HybridClock initialized: now 1786515517462676 us; error 0 us; skew 500 ppm
I20260812 06:18:37.463539 26815 webserver.cc:533] Webserver started at http://127.26.47.193:35447/ using document root <none> and password file <none>
I20260812 06:18:37.463721 26815 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:37.463793 26815 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:37.463874 26815 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:37.464318 26815 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515511783042-26815-0/minicluster-data/ts-0-root/instance:
uuid: "8e263821dce747ef8976073cd2709c33"
format_stamp: "Formatted at 2026-08-12 06:18:37 on dist-test-slave-gsp7"
I20260812 06:18:37.466001 26815 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:37.466995 27308 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:37.467245 26815 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:37.467337 26815 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515511783042-26815-0/minicluster-data/ts-0-root
uuid: "8e263821dce747ef8976073cd2709c33"
format_stamp: "Formatted at 2026-08-12 06:18:37 on dist-test-slave-gsp7"
I20260812 06:18:37.467430 26815 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515511783042-26815-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515511783042-26815-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515511783042-26815-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:37.474416 26815 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:37.474886 26815 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:37.475314 26815 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:37.475948 26815 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:37.476040 26815 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:37.476127 26815 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:37.476159 26815 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:37.480613 26815 rpc_server.cc:307] RPC server started. Bound to: 127.26.47.193:44017
I20260812 06:18:37.480914 27417 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.26.47.193:44017 every 8 connection(s)
I20260812 06:18:37.488976 27418 heartbeater.cc:344] Connected to a master server at 127.26.47.254:46581
I20260812 06:18:37.489122 27418 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:37.489372 27418 heartbeater.cc:507] Master 127.26.47.254:46581 requested a full tablet report, sending...
I20260812 06:18:37.490089 27193 ts_manager.cc:194] Registered new tserver with Master: 8e263821dce747ef8976073cd2709c33 (127.26.47.193:44017)
I20260812 06:18:37.490809 27193 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:60406
I20260812 06:18:37.491151 26815 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.009925864s
I20260812 06:18:37.498477 27193 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:60416:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:37.507161 27359 tablet_service.cc:1511] Processing CreateTablet for tablet f8400a3be50247068497c8fccc31480b (DEFAULT_TABLE table=heavy-update-compaction-test [id=24e472fa71404eb1bae696610de6db3e]), partition=
I20260812 06:18:37.507474 27359 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet f8400a3be50247068497c8fccc31480b. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:37.509755 27442 tablet_bootstrap.cc:492] T f8400a3be50247068497c8fccc31480b P 8e263821dce747ef8976073cd2709c33: Bootstrap starting.
I20260812 06:18:37.510655 27442 tablet_bootstrap.cc:654] T f8400a3be50247068497c8fccc31480b P 8e263821dce747ef8976073cd2709c33: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:37.512076 27442 tablet_bootstrap.cc:492] T f8400a3be50247068497c8fccc31480b P 8e263821dce747ef8976073cd2709c33: No bootstrap required, opened a new log
I20260812 06:18:37.512176 27442 ts_tablet_manager.cc:1403] T f8400a3be50247068497c8fccc31480b P 8e263821dce747ef8976073cd2709c33: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:37.512733 27442 raft_consensus.cc:359] T f8400a3be50247068497c8fccc31480b P 8e263821dce747ef8976073cd2709c33 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8e263821dce747ef8976073cd2709c33" member_type: VOTER last_known_addr { host: "127.26.47.193" port: 44017 } }
I20260812 06:18:37.512841 27442 raft_consensus.cc:385] T f8400a3be50247068497c8fccc31480b P 8e263821dce747ef8976073cd2709c33 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:37.512866 27442 raft_consensus.cc:740] T f8400a3be50247068497c8fccc31480b P 8e263821dce747ef8976073cd2709c33 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 8e263821dce747ef8976073cd2709c33, State: Initialized, Role: FOLLOWER
I20260812 06:18:37.512976 27442 consensus_queue.cc:260] T f8400a3be50247068497c8fccc31480b P 8e263821dce747ef8976073cd2709c33 [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: "8e263821dce747ef8976073cd2709c33" member_type: VOTER last_known_addr { host: "127.26.47.193" port: 44017 } }
I20260812 06:18:37.513036 27442 raft_consensus.cc:399] T f8400a3be50247068497c8fccc31480b P 8e263821dce747ef8976073cd2709c33 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:37.513059 27442 raft_consensus.cc:493] T f8400a3be50247068497c8fccc31480b P 8e263821dce747ef8976073cd2709c33 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:37.513092 27442 raft_consensus.cc:3060] T f8400a3be50247068497c8fccc31480b P 8e263821dce747ef8976073cd2709c33 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:37.513875 27442 raft_consensus.cc:515] T f8400a3be50247068497c8fccc31480b P 8e263821dce747ef8976073cd2709c33 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8e263821dce747ef8976073cd2709c33" member_type: VOTER last_known_addr { host: "127.26.47.193" port: 44017 } }
I20260812 06:18:37.514000 27442 leader_election.cc:304] T f8400a3be50247068497c8fccc31480b P 8e263821dce747ef8976073cd2709c33 [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: 8e263821dce747ef8976073cd2709c33; no voters: 
I20260812 06:18:37.514158 27442 leader_election.cc:290] T f8400a3be50247068497c8fccc31480b P 8e263821dce747ef8976073cd2709c33 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:37.514297 27444 raft_consensus.cc:2804] T f8400a3be50247068497c8fccc31480b P 8e263821dce747ef8976073cd2709c33 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:37.514487 27442 ts_tablet_manager.cc:1434] T f8400a3be50247068497c8fccc31480b P 8e263821dce747ef8976073cd2709c33: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:18:37.514523 27418 heartbeater.cc:499] Master 127.26.47.254:46581 was elected leader, sending a full tablet report...
I20260812 06:18:37.514532 27444 raft_consensus.cc:697] T f8400a3be50247068497c8fccc31480b P 8e263821dce747ef8976073cd2709c33 [term 1 LEADER]: Becoming Leader. State: Replica: 8e263821dce747ef8976073cd2709c33, State: Running, Role: LEADER
I20260812 06:18:37.514765 27444 consensus_queue.cc:237] T f8400a3be50247068497c8fccc31480b P 8e263821dce747ef8976073cd2709c33 [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: "8e263821dce747ef8976073cd2709c33" member_type: VOTER last_known_addr { host: "127.26.47.193" port: 44017 } }
I20260812 06:18:37.516018 27193 catalog_manager.cc:5719] T f8400a3be50247068497c8fccc31480b P 8e263821dce747ef8976073cd2709c33 reported cstate change: term changed from 0 to 1, leader changed from <none> to 8e263821dce747ef8976073cd2709c33 (127.26.47.193). New cstate: current_term: 1 leader_uuid: "8e263821dce747ef8976073cd2709c33" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8e263821dce747ef8976073cd2709c33" member_type: VOTER last_known_addr { host: "127.26.47.193" port: 44017 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:37.574146 26815 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.052s	user 0.017s	sys 0.005s
I20260812 06:18:37.731802 27419 maintenance_manager.cc:419] P 8e263821dce747ef8976073cd2709c33: Scheduling FlushMRSOp(f8400a3be50247068497c8fccc31480b): perf score=19.054940
I20260812 06:18:37.884333 27314 maintenance_manager.cc:643] P 8e263821dce747ef8976073cd2709c33: FlushMRSOp(f8400a3be50247068497c8fccc31480b) complete. Timing: real 0.152s	user 0.101s	sys 0.048s Metrics: {"bytes_written":12307491,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":70,"dirs.run_cpu_time_us":248,"dirs.run_wall_time_us":1006,"drs_written":1,"lbm_read_time_us":79,"lbm_reads_lt_1ms":4,"lbm_write_time_us":38331,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:18:37.885054 27419 maintenance_manager.cc:419] P 8e263821dce747ef8976073cd2709c33: Scheduling LogGCOp(f8400a3be50247068497c8fccc31480b): free 20743880 bytes of WAL
I20260812 06:18:37.885308 27314 log_reader.cc:385] T f8400a3be50247068497c8fccc31480b: removed 2 log segments from log reader
I20260812 06:18:37.885370 27314 log.cc:1079] T f8400a3be50247068497c8fccc31480b P 8e263821dce747ef8976073cd2709c33: Deleting log segment in path: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515511783042-26815-0/minicluster-data/ts-0-root/wals/f8400a3be50247068497c8fccc31480b/wal-000000001 (ops 1-6)
I20260812 06:18:37.885448 27314 log.cc:1079] T f8400a3be50247068497c8fccc31480b P 8e263821dce747ef8976073cd2709c33: Deleting log segment in path: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515511783042-26815-0/minicluster-data/ts-0-root/wals/f8400a3be50247068497c8fccc31480b/wal-000000002 (ops 7-11)
I20260812 06:18:37.890333 27314 maintenance_manager.cc:643] P 8e263821dce747ef8976073cd2709c33: LogGCOp(f8400a3be50247068497c8fccc31480b) complete. Timing: real 0.005s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:18:37.890705 27419 maintenance_manager.cc:419] P 8e263821dce747ef8976073cd2709c33: Scheduling FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b): perf score=2.188937
I20260812 06:18:37.902653 27314 maintenance_manager.cc:643] P 8e263821dce747ef8976073cd2709c33: FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b) complete. Timing: real 0.012s	user 0.004s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4265,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:37.903136 27419 maintenance_manager.cc:419] P 8e263821dce747ef8976073cd2709c33: Scheduling MajorDeltaCompactionOp(f8400a3be50247068497c8fccc31480b): perf score=1.000000
I20260812 06:18:38.051961 27314 maintenance_manager.cc:643] P 8e263821dce747ef8976073cd2709c33: MajorDeltaCompactionOp(f8400a3be50247068497c8fccc31480b) complete. Timing: real 0.149s	user 0.085s	sys 0.064s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":930,"lbm_read_time_us":10255,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26278,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1920,"thread_start_us":349,"threads_started":5,"update_count":2000}
I20260812 06:18:38.052663 27419 maintenance_manager.cc:419] P 8e263821dce747ef8976073cd2709c33: Scheduling FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b): perf score=10.126437
I20260812 06:18:38.098292 27314 maintenance_manager.cc:643] P 8e263821dce747ef8976073cd2709c33: FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b) complete. Timing: real 0.045s	user 0.030s	sys 0.015s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15260,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:38.099025 27419 maintenance_manager.cc:419] P 8e263821dce747ef8976073cd2709c33: Scheduling UndoDeltaBlockGCOp(f8400a3be50247068497c8fccc31480b): 16411397 bytes on disk
I20260812 06:18:38.099609 27314 maintenance_manager.cc:643] P 8e263821dce747ef8976073cd2709c33: UndoDeltaBlockGCOp(f8400a3be50247068497c8fccc31480b) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":89,"lbm_reads_lt_1ms":4}
I20260812 06:18:38.100174 27419 maintenance_manager.cc:419] P 8e263821dce747ef8976073cd2709c33: Scheduling FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b): perf score=2.188937
I20260812 06:18:38.117786 27314 maintenance_manager.cc:643] P 8e263821dce747ef8976073cd2709c33: FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b) complete. Timing: real 0.017s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6750,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:38.118243 27419 maintenance_manager.cc:419] P 8e263821dce747ef8976073cd2709c33: Scheduling MajorDeltaCompactionOp(f8400a3be50247068497c8fccc31480b): perf score=1.000000
I20260812 06:18:38.274854 27314 maintenance_manager.cc:643] P 8e263821dce747ef8976073cd2709c33: MajorDeltaCompactionOp(f8400a3be50247068497c8fccc31480b) complete. Timing: real 0.156s	user 0.104s	sys 0.052s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":922,"lbm_read_time_us":9444,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25636,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:38.275538 27419 maintenance_manager.cc:419] P 8e263821dce747ef8976073cd2709c33: Scheduling FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b): perf score=10.126437
I20260812 06:18:38.316056 27314 maintenance_manager.cc:643] P 8e263821dce747ef8976073cd2709c33: FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b) complete. Timing: real 0.040s	user 0.020s	sys 0.017s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17574,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:38.316649 27419 maintenance_manager.cc:419] P 8e263821dce747ef8976073cd2709c33: Scheduling FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b): perf score=2.188937
I20260812 06:18:38.330946 27314 maintenance_manager.cc:643] P 8e263821dce747ef8976073cd2709c33: FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b) complete. Timing: real 0.014s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5303,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:38.331406 27419 maintenance_manager.cc:419] P 8e263821dce747ef8976073cd2709c33: Scheduling MajorDeltaCompactionOp(f8400a3be50247068497c8fccc31480b): perf score=1.000000
I20260812 06:18:38.466511 27314 maintenance_manager.cc:643] P 8e263821dce747ef8976073cd2709c33: MajorDeltaCompactionOp(f8400a3be50247068497c8fccc31480b) complete. Timing: real 0.135s	user 0.103s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":187,"lbm_read_time_us":10202,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24879,"lbm_writes_lt_1ms":443,"mutex_wait_us":93,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4096,"update_count":2000}
I20260812 06:18:38.467188 27419 maintenance_manager.cc:419] P 8e263821dce747ef8976073cd2709c33: Scheduling FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b): perf score=10.126437
I20260812 06:18:38.509465 27314 maintenance_manager.cc:643] P 8e263821dce747ef8976073cd2709c33: FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b) complete. Timing: real 0.042s	user 0.024s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15109,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:38.510116 27419 maintenance_manager.cc:419] P 8e263821dce747ef8976073cd2709c33: Scheduling FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b): perf score=2.188937
I20260812 06:18:38.524130 27314 maintenance_manager.cc:643] P 8e263821dce747ef8976073cd2709c33: FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b) complete. Timing: real 0.014s	user 0.010s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4892,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:38.524683 27419 maintenance_manager.cc:419] P 8e263821dce747ef8976073cd2709c33: Scheduling MajorDeltaCompactionOp(f8400a3be50247068497c8fccc31480b): perf score=1.000000
I20260812 06:18:38.666079 27314 maintenance_manager.cc:643] P 8e263821dce747ef8976073cd2709c33: MajorDeltaCompactionOp(f8400a3be50247068497c8fccc31480b) complete. Timing: real 0.141s	user 0.093s	sys 0.047s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":119,"lbm_read_time_us":11354,"lbm_reads_lt_1ms":468,"lbm_write_time_us":26535,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":29824,"update_count":2000}
I20260812 06:18:38.666869 27419 maintenance_manager.cc:419] P 8e263821dce747ef8976073cd2709c33: Scheduling FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b): perf score=10.126437
I20260812 06:18:38.717329 27314 maintenance_manager.cc:643] P 8e263821dce747ef8976073cd2709c33: FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b) complete. Timing: real 0.050s	user 0.024s	sys 0.022s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17080,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:38.718257 27419 maintenance_manager.cc:419] P 8e263821dce747ef8976073cd2709c33: Scheduling FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b): perf score=2.188937
I20260812 06:18:38.733378 27314 maintenance_manager.cc:643] P 8e263821dce747ef8976073cd2709c33: FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6054,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:38.733918 27419 maintenance_manager.cc:419] P 8e263821dce747ef8976073cd2709c33: Scheduling MajorDeltaCompactionOp(f8400a3be50247068497c8fccc31480b): perf score=1.000000
I20260812 06:18:38.891193 27314 maintenance_manager.cc:643] P 8e263821dce747ef8976073cd2709c33: MajorDeltaCompactionOp(f8400a3be50247068497c8fccc31480b) complete. Timing: real 0.157s	user 0.106s	sys 0.050s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":158,"lbm_read_time_us":11776,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24045,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12288,"update_count":2000}
I20260812 06:18:38.891855 27419 maintenance_manager.cc:419] P 8e263821dce747ef8976073cd2709c33: Scheduling FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b): perf score=10.126437
I20260812 06:18:38.939464 27314 maintenance_manager.cc:643] P 8e263821dce747ef8976073cd2709c33: FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b) complete. Timing: real 0.047s	user 0.020s	sys 0.014s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15737,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:38.940014 27419 maintenance_manager.cc:419] P 8e263821dce747ef8976073cd2709c33: Scheduling FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b): perf score=2.188937
I20260812 06:18:38.951436 27314 maintenance_manager.cc:643] P 8e263821dce747ef8976073cd2709c33: FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b) complete. Timing: real 0.011s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4144,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:38.952075 27419 maintenance_manager.cc:419] P 8e263821dce747ef8976073cd2709c33: Scheduling MajorDeltaCompactionOp(f8400a3be50247068497c8fccc31480b): perf score=1.000000
I20260812 06:18:39.074482 27314 maintenance_manager.cc:643] P 8e263821dce747ef8976073cd2709c33: MajorDeltaCompactionOp(f8400a3be50247068497c8fccc31480b) complete. Timing: real 0.122s	user 0.090s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":167,"lbm_read_time_us":7763,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25322,"lbm_writes_lt_1ms":443,"mutex_wait_us":40,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":2000}
I20260812 06:18:39.075222 27419 maintenance_manager.cc:419] P 8e263821dce747ef8976073cd2709c33: Scheduling FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b): perf score=10.126437
I20260812 06:18:39.123054 27314 maintenance_manager.cc:643] P 8e263821dce747ef8976073cd2709c33: FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b) complete. Timing: real 0.048s	user 0.035s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17838,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:39.123512 27419 maintenance_manager.cc:419] P 8e263821dce747ef8976073cd2709c33: Scheduling FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b): perf score=2.188937
I20260812 06:18:39.134704 27314 maintenance_manager.cc:643] P 8e263821dce747ef8976073cd2709c33: FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4237,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:39.135442 27419 maintenance_manager.cc:419] P 8e263821dce747ef8976073cd2709c33: Scheduling FlushMRSOp(f8400a3be50247068497c8fccc31480b): perf score=1.000000
I20260812 06:18:39.164780 27314 maintenance_manager.cc:643] P 8e263821dce747ef8976073cd2709c33: FlushMRSOp(f8400a3be50247068497c8fccc31480b) complete. Timing: real 0.029s	user 0.027s	sys 0.001s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":75,"dirs.run_cpu_time_us":265,"dirs.run_wall_time_us":1250,"drs_written":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1593,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:39.165385 27419 maintenance_manager.cc:419] P 8e263821dce747ef8976073cd2709c33: Scheduling LogGCOp(f8400a3be50247068497c8fccc31480b): free 112692367 bytes of WAL
I20260812 06:18:39.165640 27314 log_reader.cc:385] T f8400a3be50247068497c8fccc31480b: removed 11 log segments from log reader
I20260812 06:18:39.165707 27314 log.cc:1079] T f8400a3be50247068497c8fccc31480b P 8e263821dce747ef8976073cd2709c33: Deleting log segment in path: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515511783042-26815-0/minicluster-data/ts-0-root/wals/f8400a3be50247068497c8fccc31480b/wal-000000003 (ops 12-16)
I20260812 06:18:39.165759 27314 log.cc:1079] T f8400a3be50247068497c8fccc31480b P 8e263821dce747ef8976073cd2709c33: Deleting log segment in path: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515511783042-26815-0/minicluster-data/ts-0-root/wals/f8400a3be50247068497c8fccc31480b/wal-000000004 (ops 17-21)
I20260812 06:18:39.165824 27314 log.cc:1079] T f8400a3be50247068497c8fccc31480b P 8e263821dce747ef8976073cd2709c33: Deleting log segment in path: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515511783042-26815-0/minicluster-data/ts-0-root/wals/f8400a3be50247068497c8fccc31480b/wal-000000005 (ops 22-26)
I20260812 06:18:39.165869 27314 log.cc:1079] T f8400a3be50247068497c8fccc31480b P 8e263821dce747ef8976073cd2709c33: Deleting log segment in path: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515511783042-26815-0/minicluster-data/ts-0-root/wals/f8400a3be50247068497c8fccc31480b/wal-000000006 (ops 27-31)
I20260812 06:18:39.165910 27314 log.cc:1079] T f8400a3be50247068497c8fccc31480b P 8e263821dce747ef8976073cd2709c33: Deleting log segment in path: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515511783042-26815-0/minicluster-data/ts-0-root/wals/f8400a3be50247068497c8fccc31480b/wal-000000007 (ops 32-36)
I20260812 06:18:39.165951 27314 log.cc:1079] T f8400a3be50247068497c8fccc31480b P 8e263821dce747ef8976073cd2709c33: Deleting log segment in path: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515511783042-26815-0/minicluster-data/ts-0-root/wals/f8400a3be50247068497c8fccc31480b/wal-000000008 (ops 37-41)
I20260812 06:18:39.165990 27314 log.cc:1079] T f8400a3be50247068497c8fccc31480b P 8e263821dce747ef8976073cd2709c33: Deleting log segment in path: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515511783042-26815-0/minicluster-data/ts-0-root/wals/f8400a3be50247068497c8fccc31480b/wal-000000009 (ops 42-46)
I20260812 06:18:39.166030 27314 log.cc:1079] T f8400a3be50247068497c8fccc31480b P 8e263821dce747ef8976073cd2709c33: Deleting log segment in path: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515511783042-26815-0/minicluster-data/ts-0-root/wals/f8400a3be50247068497c8fccc31480b/wal-000000010 (ops 47-51)
I20260812 06:18:39.166071 27314 log.cc:1079] T f8400a3be50247068497c8fccc31480b P 8e263821dce747ef8976073cd2709c33: Deleting log segment in path: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515511783042-26815-0/minicluster-data/ts-0-root/wals/f8400a3be50247068497c8fccc31480b/wal-000000011 (ops 52-56)
I20260812 06:18:39.166110 27314 log.cc:1079] T f8400a3be50247068497c8fccc31480b P 8e263821dce747ef8976073cd2709c33: Deleting log segment in path: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515511783042-26815-0/minicluster-data/ts-0-root/wals/f8400a3be50247068497c8fccc31480b/wal-000000012 (ops 57-61)
I20260812 06:18:39.166150 27314 log.cc:1079] T f8400a3be50247068497c8fccc31480b P 8e263821dce747ef8976073cd2709c33: Deleting log segment in path: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515511783042-26815-0/minicluster-data/ts-0-root/wals/f8400a3be50247068497c8fccc31480b/wal-000000013 (ops 62-66)
I20260812 06:18:39.190304 27314 maintenance_manager.cc:643] P 8e263821dce747ef8976073cd2709c33: LogGCOp(f8400a3be50247068497c8fccc31480b) complete. Timing: real 0.025s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:18:39.190814 27419 maintenance_manager.cc:419] P 8e263821dce747ef8976073cd2709c33: Scheduling FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b): perf score=3.181125
I20260812 06:18:39.209975 27314 maintenance_manager.cc:643] P 8e263821dce747ef8976073cd2709c33: FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b) complete. Timing: real 0.019s	user 0.017s	sys 0.000s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":7234,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:39.210441 27419 maintenance_manager.cc:419] P 8e263821dce747ef8976073cd2709c33: Scheduling UndoDeltaBlockGCOp(f8400a3be50247068497c8fccc31480b): 447 bytes on disk
I20260812 06:18:39.210836 27314 maintenance_manager.cc:643] P 8e263821dce747ef8976073cd2709c33: UndoDeltaBlockGCOp(f8400a3be50247068497c8fccc31480b) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4}
I20260812 06:18:39.211280 27419 maintenance_manager.cc:419] P 8e263821dce747ef8976073cd2709c33: Scheduling FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b): perf score=2.188937
I20260812 06:18:39.221271 27314 maintenance_manager.cc:643] P 8e263821dce747ef8976073cd2709c33: FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3725,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:39.221779 27419 maintenance_manager.cc:419] P 8e263821dce747ef8976073cd2709c33: Scheduling MajorDeltaCompactionOp(f8400a3be50247068497c8fccc31480b): perf score=1.000000
I20260812 06:18:39.388849 27314 maintenance_manager.cc:643] P 8e263821dce747ef8976073cd2709c33: MajorDeltaCompactionOp(f8400a3be50247068497c8fccc31480b) complete. Timing: real 0.167s	user 0.127s	sys 0.038s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877328,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1043,"lbm_read_time_us":11892,"lbm_reads_lt_1ms":674,"lbm_write_time_us":33601,"lbm_writes_lt_1ms":643,"mutex_wait_us":121,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":8064,"thread_start_us":82,"threads_started":1,"update_count":3000}
I20260812 06:18:39.389441 27419 maintenance_manager.cc:419] P 8e263821dce747ef8976073cd2709c33: Scheduling FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b): perf score=14.095187
I20260812 06:18:39.440536 27314 maintenance_manager.cc:643] P 8e263821dce747ef8976073cd2709c33: FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b) complete. Timing: real 0.051s	user 0.028s	sys 0.017s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21435,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:39.441021 27419 maintenance_manager.cc:419] P 8e263821dce747ef8976073cd2709c33: Scheduling FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b): perf score=2.188937
I20260812 06:18:39.453629 27314 maintenance_manager.cc:643] P 8e263821dce747ef8976073cd2709c33: FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b) complete. Timing: real 0.012s	user 0.005s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4315,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:39.454083 27419 maintenance_manager.cc:419] P 8e263821dce747ef8976073cd2709c33: Scheduling MajorDeltaCompactionOp(f8400a3be50247068497c8fccc31480b): perf score=1.000000
I20260812 06:18:39.604501 27314 maintenance_manager.cc:643] P 8e263821dce747ef8976073cd2709c33: MajorDeltaCompactionOp(f8400a3be50247068497c8fccc31480b) complete. Timing: real 0.150s	user 0.099s	sys 0.043s 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":447,"lbm_read_time_us":9151,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27751,"lbm_writes_lt_1ms":543,"mutex_wait_us":1,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5760,"update_count":2500}
I20260812 06:18:39.605266 27419 maintenance_manager.cc:419] P 8e263821dce747ef8976073cd2709c33: Scheduling FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b): perf score=14.095187
I20260812 06:18:39.669581 27314 maintenance_manager.cc:643] P 8e263821dce747ef8976073cd2709c33: FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b) complete. Timing: real 0.064s	user 0.037s	sys 0.015s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":21876,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:39.670117 27419 maintenance_manager.cc:419] P 8e263821dce747ef8976073cd2709c33: Scheduling FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b): perf score=2.188937
I20260812 06:18:39.680572 27314 maintenance_manager.cc:643] P 8e263821dce747ef8976073cd2709c33: FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3882,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:39.681205 27419 maintenance_manager.cc:419] P 8e263821dce747ef8976073cd2709c33: Scheduling MajorDeltaCompactionOp(f8400a3be50247068497c8fccc31480b): perf score=1.000000
I20260812 06:18:39.855170 27314 maintenance_manager.cc:643] P 8e263821dce747ef8976073cd2709c33: MajorDeltaCompactionOp(f8400a3be50247068497c8fccc31480b) complete. Timing: real 0.174s	user 0.107s	sys 0.062s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":170,"lbm_read_time_us":12732,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27447,"lbm_writes_lt_1ms":543,"mutex_wait_us":40,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4352,"update_count":2500}
I20260812 06:18:39.855823 27419 maintenance_manager.cc:419] P 8e263821dce747ef8976073cd2709c33: Scheduling FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b): perf score=14.095187
I20260812 06:18:39.916972 27314 maintenance_manager.cc:643] P 8e263821dce747ef8976073cd2709c33: FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b) complete. Timing: real 0.061s	user 0.026s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19035,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:39.917743 27419 maintenance_manager.cc:419] P 8e263821dce747ef8976073cd2709c33: Scheduling FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b): perf score=2.188937
I20260812 06:18:39.929804 27314 maintenance_manager.cc:643] P 8e263821dce747ef8976073cd2709c33: FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4409,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:39.931931 27419 maintenance_manager.cc:419] P 8e263821dce747ef8976073cd2709c33: Scheduling MajorDeltaCompactionOp(f8400a3be50247068497c8fccc31480b): perf score=1.000000
I20260812 06:18:40.100770 27314 maintenance_manager.cc:643] P 8e263821dce747ef8976073cd2709c33: MajorDeltaCompactionOp(f8400a3be50247068497c8fccc31480b) complete. Timing: real 0.169s	user 0.106s	sys 0.056s 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":978,"lbm_read_time_us":10454,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25859,"lbm_writes_lt_1ms":543,"mutex_wait_us":259,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:18:40.101544 27419 maintenance_manager.cc:419] P 8e263821dce747ef8976073cd2709c33: Scheduling FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b): perf score=14.095187
I20260812 06:18:40.162918 27314 maintenance_manager.cc:643] P 8e263821dce747ef8976073cd2709c33: FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b) complete. Timing: real 0.061s	user 0.025s	sys 0.032s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":21910,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:40.163590 27419 maintenance_manager.cc:419] P 8e263821dce747ef8976073cd2709c33: Scheduling FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b): perf score=2.188937
I20260812 06:18:40.174736 27314 maintenance_manager.cc:643] P 8e263821dce747ef8976073cd2709c33: FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4308,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:40.175428 27419 maintenance_manager.cc:419] P 8e263821dce747ef8976073cd2709c33: Scheduling MajorDeltaCompactionOp(f8400a3be50247068497c8fccc31480b): perf score=1.000000
I20260812 06:18:40.351984 27314 maintenance_manager.cc:643] P 8e263821dce747ef8976073cd2709c33: MajorDeltaCompactionOp(f8400a3be50247068497c8fccc31480b) complete. Timing: real 0.176s	user 0.092s	sys 0.076s 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":927,"lbm_read_time_us":12726,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26389,"lbm_writes_lt_1ms":543,"mutex_wait_us":271,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2500}
I20260812 06:18:40.352660 27419 maintenance_manager.cc:419] P 8e263821dce747ef8976073cd2709c33: Scheduling FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b): perf score=14.095187
I20260812 06:18:40.402853 27314 maintenance_manager.cc:643] P 8e263821dce747ef8976073cd2709c33: FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b) complete. Timing: real 0.050s	user 0.038s	sys 0.004s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19437,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:40.403342 27419 maintenance_manager.cc:419] P 8e263821dce747ef8976073cd2709c33: Scheduling FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b): perf score=2.188937
I20260812 06:18:40.424124 27314 maintenance_manager.cc:643] P 8e263821dce747ef8976073cd2709c33: FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b) complete. Timing: real 0.021s	user 0.007s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4204,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:40.424747 27419 maintenance_manager.cc:419] P 8e263821dce747ef8976073cd2709c33: Scheduling MajorDeltaCompactionOp(f8400a3be50247068497c8fccc31480b): perf score=1.000000
I20260812 06:18:40.610803 27314 maintenance_manager.cc:643] P 8e263821dce747ef8976073cd2709c33: MajorDeltaCompactionOp(f8400a3be50247068497c8fccc31480b) complete. Timing: real 0.186s	user 0.145s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":160,"lbm_read_time_us":12660,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31895,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3840,"update_count":2500}
I20260812 06:18:40.611397 27419 maintenance_manager.cc:419] P 8e263821dce747ef8976073cd2709c33: Scheduling FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b): perf score=14.095187
I20260812 06:18:40.671047 27314 maintenance_manager.cc:643] P 8e263821dce747ef8976073cd2709c33: FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b) complete. Timing: real 0.059s	user 0.040s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24822,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:40.671558 27419 maintenance_manager.cc:419] P 8e263821dce747ef8976073cd2709c33: Scheduling FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b): perf score=2.188937
I20260812 06:18:40.682590 27314 maintenance_manager.cc:643] P 8e263821dce747ef8976073cd2709c33: FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3871,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:40.683290 27419 maintenance_manager.cc:419] P 8e263821dce747ef8976073cd2709c33: Scheduling FlushMRSOp(f8400a3be50247068497c8fccc31480b): perf score=1.000000
I20260812 06:18:40.722604 27314 maintenance_manager.cc:643] P 8e263821dce747ef8976073cd2709c33: FlushMRSOp(f8400a3be50247068497c8fccc31480b) complete. Timing: real 0.039s	user 0.037s	sys 0.000s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":2300,"dirs.run_cpu_time_us":200,"dirs.run_wall_time_us":1469,"drs_written":1,"lbm_read_time_us":89,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2323,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:18:40.723426 27419 maintenance_manager.cc:419] P 8e263821dce747ef8976073cd2709c33: Scheduling LogGCOp(f8400a3be50247068497c8fccc31480b): free 133024372 bytes of WAL
I20260812 06:18:40.723680 27314 log_reader.cc:385] T f8400a3be50247068497c8fccc31480b: removed 13 log segments from log reader
I20260812 06:18:40.723742 27314 log.cc:1079] T f8400a3be50247068497c8fccc31480b P 8e263821dce747ef8976073cd2709c33: Deleting log segment in path: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515511783042-26815-0/minicluster-data/ts-0-root/wals/f8400a3be50247068497c8fccc31480b/wal-000000014 (ops 67-71)
I20260812 06:18:40.723825 27314 log.cc:1079] T f8400a3be50247068497c8fccc31480b P 8e263821dce747ef8976073cd2709c33: Deleting log segment in path: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515511783042-26815-0/minicluster-data/ts-0-root/wals/f8400a3be50247068497c8fccc31480b/wal-000000015 (ops 72-76)
I20260812 06:18:40.723872 27314 log.cc:1079] T f8400a3be50247068497c8fccc31480b P 8e263821dce747ef8976073cd2709c33: Deleting log segment in path: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515511783042-26815-0/minicluster-data/ts-0-root/wals/f8400a3be50247068497c8fccc31480b/wal-000000016 (ops 77-81)
I20260812 06:18:40.723907 27314 log.cc:1079] T f8400a3be50247068497c8fccc31480b P 8e263821dce747ef8976073cd2709c33: Deleting log segment in path: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515511783042-26815-0/minicluster-data/ts-0-root/wals/f8400a3be50247068497c8fccc31480b/wal-000000017 (ops 82-86)
I20260812 06:18:40.723950 27314 log.cc:1079] T f8400a3be50247068497c8fccc31480b P 8e263821dce747ef8976073cd2709c33: Deleting log segment in path: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515511783042-26815-0/minicluster-data/ts-0-root/wals/f8400a3be50247068497c8fccc31480b/wal-000000018 (ops 87-91)
I20260812 06:18:40.723994 27314 log.cc:1079] T f8400a3be50247068497c8fccc31480b P 8e263821dce747ef8976073cd2709c33: Deleting log segment in path: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515511783042-26815-0/minicluster-data/ts-0-root/wals/f8400a3be50247068497c8fccc31480b/wal-000000019 (ops 92-96)
I20260812 06:18:40.724035 27314 log.cc:1079] T f8400a3be50247068497c8fccc31480b P 8e263821dce747ef8976073cd2709c33: Deleting log segment in path: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515511783042-26815-0/minicluster-data/ts-0-root/wals/f8400a3be50247068497c8fccc31480b/wal-000000020 (ops 97-101)
I20260812 06:18:40.724077 27314 log.cc:1079] T f8400a3be50247068497c8fccc31480b P 8e263821dce747ef8976073cd2709c33: Deleting log segment in path: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515511783042-26815-0/minicluster-data/ts-0-root/wals/f8400a3be50247068497c8fccc31480b/wal-000000021 (ops 102-106)
I20260812 06:18:40.724121 27314 log.cc:1079] T f8400a3be50247068497c8fccc31480b P 8e263821dce747ef8976073cd2709c33: Deleting log segment in path: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515511783042-26815-0/minicluster-data/ts-0-root/wals/f8400a3be50247068497c8fccc31480b/wal-000000022 (ops 107-111)
I20260812 06:18:40.724181 27314 log.cc:1079] T f8400a3be50247068497c8fccc31480b P 8e263821dce747ef8976073cd2709c33: Deleting log segment in path: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515511783042-26815-0/minicluster-data/ts-0-root/wals/f8400a3be50247068497c8fccc31480b/wal-000000023 (ops 112-116)
I20260812 06:18:40.724253 27314 log.cc:1079] T f8400a3be50247068497c8fccc31480b P 8e263821dce747ef8976073cd2709c33: Deleting log segment in path: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515511783042-26815-0/minicluster-data/ts-0-root/wals/f8400a3be50247068497c8fccc31480b/wal-000000024 (ops 117-120)
I20260812 06:18:40.724295 27314 log.cc:1079] T f8400a3be50247068497c8fccc31480b P 8e263821dce747ef8976073cd2709c33: Deleting log segment in path: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515511783042-26815-0/minicluster-data/ts-0-root/wals/f8400a3be50247068497c8fccc31480b/wal-000000025 (ops 121-125)
I20260812 06:18:40.724329 27314 log.cc:1079] T f8400a3be50247068497c8fccc31480b P 8e263821dce747ef8976073cd2709c33: Deleting log segment in path: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515511783042-26815-0/minicluster-data/ts-0-root/wals/f8400a3be50247068497c8fccc31480b/wal-000000026 (ops 126-130)
I20260812 06:18:40.752269 27314 maintenance_manager.cc:643] P 8e263821dce747ef8976073cd2709c33: LogGCOp(f8400a3be50247068497c8fccc31480b) complete. Timing: real 0.029s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:18:40.752779 27419 maintenance_manager.cc:419] P 8e263821dce747ef8976073cd2709c33: Scheduling FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b): perf score=3.181125
I20260812 06:18:40.775907 27314 maintenance_manager.cc:643] P 8e263821dce747ef8976073cd2709c33: FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b) complete. Timing: real 0.023s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":5089,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:40.776444 27419 maintenance_manager.cc:419] P 8e263821dce747ef8976073cd2709c33: Scheduling FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b): perf score=2.188937
I20260812 06:18:40.790237 27314 maintenance_manager.cc:643] P 8e263821dce747ef8976073cd2709c33: FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b) complete. Timing: real 0.014s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5039,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:40.790874 27419 maintenance_manager.cc:419] P 8e263821dce747ef8976073cd2709c33: Scheduling UndoDeltaBlockGCOp(f8400a3be50247068497c8fccc31480b): 492 bytes on disk
I20260812 06:18:40.791567 27314 maintenance_manager.cc:643] P 8e263821dce747ef8976073cd2709c33: UndoDeltaBlockGCOp(f8400a3be50247068497c8fccc31480b) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":92,"lbm_reads_lt_1ms":4}
I20260812 06:18:40.792179 27419 maintenance_manager.cc:419] P 8e263821dce747ef8976073cd2709c33: Scheduling MajorDeltaCompactionOp(f8400a3be50247068497c8fccc31480b): perf score=1.000000
I20260812 06:18:41.025949 27314 maintenance_manager.cc:643] P 8e263821dce747ef8976073cd2709c33: MajorDeltaCompactionOp(f8400a3be50247068497c8fccc31480b) complete. Timing: real 0.234s	user 0.145s	sys 0.084s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979740,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":674,"dirs.run_cpu_time_us":695,"dirs.run_wall_time_us":4720,"lbm_read_time_us":16044,"lbm_reads_lt_1ms":774,"lbm_write_time_us":35978,"lbm_writes_lt_1ms":743,"mutex_wait_us":75,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":4224,"thread_start_us":89,"threads_started":1,"update_count":3500}
I20260812 06:18:41.026714 27419 maintenance_manager.cc:419] P 8e263821dce747ef8976073cd2709c33: Scheduling FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b): perf score=18.063937
I20260812 06:18:41.095455 27314 maintenance_manager.cc:643] P 8e263821dce747ef8976073cd2709c33: FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b) complete. Timing: real 0.069s	user 0.044s	sys 0.013s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":26676,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:41.095968 27419 maintenance_manager.cc:419] P 8e263821dce747ef8976073cd2709c33: Scheduling FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b): perf score=2.188937
I20260812 06:18:41.107688 27314 maintenance_manager.cc:643] P 8e263821dce747ef8976073cd2709c33: FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3888,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:41.108287 27419 maintenance_manager.cc:419] P 8e263821dce747ef8976073cd2709c33: Scheduling MajorDeltaCompactionOp(f8400a3be50247068497c8fccc31480b): perf score=1.000000
I20260812 06:18:41.307324 27314 maintenance_manager.cc:643] P 8e263821dce747ef8976073cd2709c33: MajorDeltaCompactionOp(f8400a3be50247068497c8fccc31480b) complete. Timing: real 0.199s	user 0.107s	sys 0.091s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877103,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":341,"lbm_read_time_us":13562,"lbm_reads_lt_1ms":672,"lbm_write_time_us":34650,"lbm_writes_lt_1ms":643,"mutex_wait_us":56,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":18816,"update_count":3000}
I20260812 06:18:41.308120 27419 maintenance_manager.cc:419] P 8e263821dce747ef8976073cd2709c33: Scheduling FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b): perf score=14.095187
I20260812 06:18:41.362716 27314 maintenance_manager.cc:643] P 8e263821dce747ef8976073cd2709c33: FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b) complete. Timing: real 0.054s	user 0.039s	sys 0.008s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20994,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:18:41.363377 27419 maintenance_manager.cc:419] P 8e263821dce747ef8976073cd2709c33: Scheduling FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b): perf score=2.188937
I20260812 06:18:41.376129 27314 maintenance_manager.cc:643] P 8e263821dce747ef8976073cd2709c33: FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b) complete. Timing: real 0.013s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4779,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:41.376842 27419 maintenance_manager.cc:419] P 8e263821dce747ef8976073cd2709c33: Scheduling MajorDeltaCompactionOp(f8400a3be50247068497c8fccc31480b): perf score=1.000000
I20260812 06:18:41.561026 27314 maintenance_manager.cc:643] P 8e263821dce747ef8976073cd2709c33: MajorDeltaCompactionOp(f8400a3be50247068497c8fccc31480b) complete. Timing: real 0.184s	user 0.143s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":765,"lbm_read_time_us":14579,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30508,"lbm_writes_lt_1ms":543,"mutex_wait_us":338,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6528,"update_count":2500}
I20260812 06:18:41.561583 27419 maintenance_manager.cc:419] P 8e263821dce747ef8976073cd2709c33: Scheduling FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b): perf score=14.095187
I20260812 06:18:41.613986 27314 maintenance_manager.cc:643] P 8e263821dce747ef8976073cd2709c33: FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b) complete. Timing: real 0.052s	user 0.016s	sys 0.033s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21121,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:41.614498 27419 maintenance_manager.cc:419] P 8e263821dce747ef8976073cd2709c33: Scheduling FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b): perf score=2.188937
I20260812 06:18:41.631827 27314 maintenance_manager.cc:643] P 8e263821dce747ef8976073cd2709c33: FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b) complete. Timing: real 0.017s	user 0.011s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6846,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:41.632367 27419 maintenance_manager.cc:419] P 8e263821dce747ef8976073cd2709c33: Scheduling MajorDeltaCompactionOp(f8400a3be50247068497c8fccc31480b): perf score=1.000000
I20260812 06:18:41.812871 27314 maintenance_manager.cc:643] P 8e263821dce747ef8976073cd2709c33: MajorDeltaCompactionOp(f8400a3be50247068497c8fccc31480b) complete. Timing: real 0.180s	user 0.124s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":321,"lbm_read_time_us":13211,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31960,"lbm_writes_lt_1ms":543,"mutex_wait_us":52,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:41.813794 27419 maintenance_manager.cc:419] P 8e263821dce747ef8976073cd2709c33: Scheduling FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b): perf score=14.095187
I20260812 06:18:41.878589 27314 maintenance_manager.cc:643] P 8e263821dce747ef8976073cd2709c33: FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b) complete. Timing: real 0.065s	user 0.037s	sys 0.021s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20492,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:41.879179 27419 maintenance_manager.cc:419] P 8e263821dce747ef8976073cd2709c33: Scheduling FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b): perf score=2.188937
I20260812 06:18:41.896404 27314 maintenance_manager.cc:643] P 8e263821dce747ef8976073cd2709c33: FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b) complete. Timing: real 0.017s	user 0.007s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6524,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:41.897086 27419 maintenance_manager.cc:419] P 8e263821dce747ef8976073cd2709c33: Scheduling MajorDeltaCompactionOp(f8400a3be50247068497c8fccc31480b): perf score=1.000000
I20260812 06:18:42.101805 27314 maintenance_manager.cc:643] P 8e263821dce747ef8976073cd2709c33: MajorDeltaCompactionOp(f8400a3be50247068497c8fccc31480b) complete. Timing: real 0.204s	user 0.105s	sys 0.088s 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":984,"lbm_read_time_us":14619,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34316,"lbm_writes_lt_1ms":543,"mutex_wait_us":345,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11392,"update_count":2500}
I20260812 06:18:42.102473 27419 maintenance_manager.cc:419] P 8e263821dce747ef8976073cd2709c33: Scheduling FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b): perf score=14.095187
I20260812 06:18:42.159790 27314 maintenance_manager.cc:643] P 8e263821dce747ef8976073cd2709c33: FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b) complete. Timing: real 0.057s	user 0.027s	sys 0.027s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20834,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:42.160429 27419 maintenance_manager.cc:419] P 8e263821dce747ef8976073cd2709c33: Scheduling FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b): perf score=2.188937
I20260812 06:18:42.171574 27314 maintenance_manager.cc:643] P 8e263821dce747ef8976073cd2709c33: FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b) complete. Timing: real 0.011s	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:18:42.172060 27419 maintenance_manager.cc:419] P 8e263821dce747ef8976073cd2709c33: Scheduling FlushMRSOp(f8400a3be50247068497c8fccc31480b): perf score=1.000000
I20260812 06:18:42.216475 27314 maintenance_manager.cc:643] P 8e263821dce747ef8976073cd2709c33: FlushMRSOp(f8400a3be50247068497c8fccc31480b) complete. Timing: real 0.044s	user 0.028s	sys 0.003s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":66,"dirs.run_cpu_time_us":165,"dirs.run_wall_time_us":1132,"drs_written":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1530,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:42.217213 27419 maintenance_manager.cc:419] P 8e263821dce747ef8976073cd2709c33: Scheduling LogGCOp(f8400a3be50247068497c8fccc31480b): free 115943419 bytes of WAL
I20260812 06:18:42.217461 27314 log_reader.cc:385] T f8400a3be50247068497c8fccc31480b: removed 11 log segments from log reader
I20260812 06:18:42.217564 27314 log.cc:1079] T f8400a3be50247068497c8fccc31480b P 8e263821dce747ef8976073cd2709c33: Deleting log segment in path: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515511783042-26815-0/minicluster-data/ts-0-root/wals/f8400a3be50247068497c8fccc31480b/wal-000000027 (ops 131-135)
I20260812 06:18:42.217621 27314 log.cc:1079] T f8400a3be50247068497c8fccc31480b P 8e263821dce747ef8976073cd2709c33: Deleting log segment in path: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515511783042-26815-0/minicluster-data/ts-0-root/wals/f8400a3be50247068497c8fccc31480b/wal-000000028 (ops 136-140)
I20260812 06:18:42.217679 27314 log.cc:1079] T f8400a3be50247068497c8fccc31480b P 8e263821dce747ef8976073cd2709c33: Deleting log segment in path: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515511783042-26815-0/minicluster-data/ts-0-root/wals/f8400a3be50247068497c8fccc31480b/wal-000000029 (ops 141-145)
I20260812 06:18:42.217723 27314 log.cc:1079] T f8400a3be50247068497c8fccc31480b P 8e263821dce747ef8976073cd2709c33: Deleting log segment in path: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515511783042-26815-0/minicluster-data/ts-0-root/wals/f8400a3be50247068497c8fccc31480b/wal-000000030 (ops 146-150)
I20260812 06:18:42.217760 27314 log.cc:1079] T f8400a3be50247068497c8fccc31480b P 8e263821dce747ef8976073cd2709c33: Deleting log segment in path: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515511783042-26815-0/minicluster-data/ts-0-root/wals/f8400a3be50247068497c8fccc31480b/wal-000000031 (ops 151-155)
I20260812 06:18:42.217809 27314 log.cc:1079] T f8400a3be50247068497c8fccc31480b P 8e263821dce747ef8976073cd2709c33: Deleting log segment in path: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515511783042-26815-0/minicluster-data/ts-0-root/wals/f8400a3be50247068497c8fccc31480b/wal-000000032 (ops 156-160)
I20260812 06:18:42.217849 27314 log.cc:1079] T f8400a3be50247068497c8fccc31480b P 8e263821dce747ef8976073cd2709c33: Deleting log segment in path: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515511783042-26815-0/minicluster-data/ts-0-root/wals/f8400a3be50247068497c8fccc31480b/wal-000000033 (ops 161-165)
I20260812 06:18:42.217888 27314 log.cc:1079] T f8400a3be50247068497c8fccc31480b P 8e263821dce747ef8976073cd2709c33: Deleting log segment in path: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515511783042-26815-0/minicluster-data/ts-0-root/wals/f8400a3be50247068497c8fccc31480b/wal-000000034 (ops 166-170)
I20260812 06:18:42.217928 27314 log.cc:1079] T f8400a3be50247068497c8fccc31480b P 8e263821dce747ef8976073cd2709c33: Deleting log segment in path: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515511783042-26815-0/minicluster-data/ts-0-root/wals/f8400a3be50247068497c8fccc31480b/wal-000000035 (ops 171-175)
I20260812 06:18:42.217967 27314 log.cc:1079] T f8400a3be50247068497c8fccc31480b P 8e263821dce747ef8976073cd2709c33: Deleting log segment in path: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515511783042-26815-0/minicluster-data/ts-0-root/wals/f8400a3be50247068497c8fccc31480b/wal-000000036 (ops 176-180)
I20260812 06:18:42.218007 27314 log.cc:1079] T f8400a3be50247068497c8fccc31480b P 8e263821dce747ef8976073cd2709c33: Deleting log segment in path: /tmp/dist-test-taskrGZto1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515511783042-26815-0/minicluster-data/ts-0-root/wals/f8400a3be50247068497c8fccc31480b/wal-000000037 (ops 181-185)
I20260812 06:18:42.244088 27314 maintenance_manager.cc:643] P 8e263821dce747ef8976073cd2709c33: LogGCOp(f8400a3be50247068497c8fccc31480b) complete. Timing: real 0.027s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:18:42.244563 27419 maintenance_manager.cc:419] P 8e263821dce747ef8976073cd2709c33: Scheduling UndoDeltaBlockGCOp(f8400a3be50247068497c8fccc31480b): 448 bytes on disk
I20260812 06:18:42.245163 27314 maintenance_manager.cc:643] P 8e263821dce747ef8976073cd2709c33: UndoDeltaBlockGCOp(f8400a3be50247068497c8fccc31480b) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":65,"lbm_reads_lt_1ms":4}
I20260812 06:18:42.245857 27419 maintenance_manager.cc:419] P 8e263821dce747ef8976073cd2709c33: Scheduling FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b): perf score=2.188937
I20260812 06:18:42.260538 27314 maintenance_manager.cc:643] P 8e263821dce747ef8976073cd2709c33: FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b) complete. Timing: real 0.015s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4143684,"delete_count":0,"lbm_write_time_us":4444,"lbm_writes_lt_1ms":104,"reinsert_count":0,"update_count":505}
I20260812 06:18:42.261005 27419 maintenance_manager.cc:419] P 8e263821dce747ef8976073cd2709c33: Scheduling FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b): perf score=2.188937
I20260812 06:18:42.271649 27314 maintenance_manager.cc:643] P 8e263821dce747ef8976073cd2709c33: FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4061634,"delete_count":0,"lbm_write_time_us":3919,"lbm_writes_lt_1ms":102,"reinsert_count":0,"update_count":495}
I20260812 06:18:42.272185 27419 maintenance_manager.cc:419] P 8e263821dce747ef8976073cd2709c33: Scheduling MajorDeltaCompactionOp(f8400a3be50247068497c8fccc31480b): perf score=1.000000
I20260812 06:18:42.521634 27314 maintenance_manager.cc:643] P 8e263821dce747ef8976073cd2709c33: MajorDeltaCompactionOp(f8400a3be50247068497c8fccc31480b) complete. Timing: real 0.249s	user 0.172s	sys 0.072s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979750,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1016,"lbm_read_time_us":14405,"lbm_reads_lt_1ms":774,"lbm_write_time_us":42178,"lbm_writes_lt_1ms":743,"mutex_wait_us":30,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":134,"threads_started":1,"update_count":3500}
I20260812 06:18:42.522475 27419 maintenance_manager.cc:419] P 8e263821dce747ef8976073cd2709c33: Scheduling FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b): perf score=18.063937
I20260812 06:18:42.591451 27314 maintenance_manager.cc:643] P 8e263821dce747ef8976073cd2709c33: FlushDeltaMemStoresOp(f8400a3be50247068497c8fccc31480b) complete. Timing: real 0.069s	user 0.044s	sys 0.022s Metrics: {"bytes_written":20512318,"delete_count":0,"lbm_write_time_us":31395,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:42.592183 27419 maintenance_manager.cc:419] P 8e263821dce747ef8976073cd2709c33: Scheduling MajorDeltaCompactionOp(f8400a3be50247068497c8fccc31480b): perf score=1.000000
I20260812 06:18:42.611987 26815 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.038s	user 1.878s	sys 0.200s
I20260812 06:18:42.684556 26815 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.072s	user 0.001s	sys 0.000s
I20260812 06:18:42.685127 26815 tablet_server.cc:179] TabletServer@127.26.47.193:0 shutting down...
I20260812 06:18:42.749643 27314 maintenance_manager.cc:643] P 8e263821dce747ef8976073cd2709c33: MajorDeltaCompactionOp(f8400a3be50247068497c8fccc31480b) complete. Timing: real 0.157s	user 0.112s	sys 0.044s Metrics: {"cfile_cache_miss":531,"cfile_cache_miss_bytes":24774574,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1027,"lbm_read_time_us":12658,"lbm_reads_lt_1ms":559,"lbm_write_time_us":26631,"lbm_writes_lt_1ms":543,"mutex_wait_us":248,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":65408,"update_count":2500}
I20260812 06:18:42.750389 26815 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:42.750659 26815 tablet_replica.cc:333] T f8400a3be50247068497c8fccc31480b P 8e263821dce747ef8976073cd2709c33: stopping tablet replica
I20260812 06:18:42.750846 26815 raft_consensus.cc:2243] T f8400a3be50247068497c8fccc31480b P 8e263821dce747ef8976073cd2709c33 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:42.751040 26815 raft_consensus.cc:2272] T f8400a3be50247068497c8fccc31480b P 8e263821dce747ef8976073cd2709c33 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:42.755807 26815 tablet_server.cc:196] TabletServer@127.26.47.193:0 shutdown complete.
I20260812 06:18:42.794312 26815 master.cc:562] Master@127.26.47.254:46581 shutting down...
I20260812 06:18:42.797894 26815 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 451ed6a4da04412fa6de6c8eb102cc3d [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:42.798126 26815 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 451ed6a4da04412fa6de6c8eb102cc3d [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:42.798215 26815 tablet_replica.cc:333] T 00000000000000000000000000000000 P 451ed6a4da04412fa6de6c8eb102cc3d: stopping tablet replica
I20260812 06:18:42.810979 26815 master.cc:584] Master@127.26.47.254:46581 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5558 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11107 ms total)

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