[==========] 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:50.651055  6406 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.6.65.190:45307
I20260812 06:18:50.652556  6406 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:50.653523  6406 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:50.661854  6413 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:50.661854  6416 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:50.662206  6406 server_base.cc:1061] running on GCE node
W20260812 06:18:50.662556  6412 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:50.663271  6406 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:50.663465  6406 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:50.663540  6406 hybrid_clock.cc:648] HybridClock initialized: now 1786515530663535 us; error 0 us; skew 500 ppm
I20260812 06:18:50.666348  6406 webserver.cc:533] Webserver started at http://127.6.65.190:34379/ using document root <none> and password file <none>
I20260812 06:18:50.667150  6406 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:50.667279  6406 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:50.667591  6406 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:50.669723  6406 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515530638234-6406-0/minicluster-data/master-0-root/instance:
uuid: "d972c1d6536644749f69b33d4a3cb111"
format_stamp: "Formatted at 2026-08-12 06:18:50 on dist-test-slave-77v9"
I20260812 06:18:50.678570  6406 fs_manager.cc:696] Time spent creating directory manager: real 0.008s	user 0.006s	sys 0.000s
I20260812 06:18:50.682919  6422 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:50.688967  6406 fs_manager.cc:730] Time spent opening block manager: real 0.008s	user 0.004s	sys 0.000s
I20260812 06:18:50.689260  6406 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515530638234-6406-0/minicluster-data/master-0-root
uuid: "d972c1d6536644749f69b33d4a3cb111"
format_stamp: "Formatted at 2026-08-12 06:18:50 on dist-test-slave-77v9"
I20260812 06:18:50.689476  6406 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515530638234-6406-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515530638234-6406-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515530638234-6406-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:50.721798  6406 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:50.722971  6406 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:50.723261  6406 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:50.736078  6406 rpc_server.cc:307] RPC server started. Bound to: 127.6.65.190:45307
I20260812 06:18:50.736071  6479 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.6.65.190:45307 every 8 connection(s)
I20260812 06:18:50.739332  6481 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:50.746939  6481 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P d972c1d6536644749f69b33d4a3cb111: Bootstrap starting.
I20260812 06:18:50.750447  6481 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P d972c1d6536644749f69b33d4a3cb111: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:50.751732  6481 log.cc:826] T 00000000000000000000000000000000 P d972c1d6536644749f69b33d4a3cb111: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:50.754292  6481 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P d972c1d6536644749f69b33d4a3cb111: No bootstrap required, opened a new log
I20260812 06:18:50.757851  6481 raft_consensus.cc:359] T 00000000000000000000000000000000 P d972c1d6536644749f69b33d4a3cb111 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d972c1d6536644749f69b33d4a3cb111" member_type: VOTER }
I20260812 06:18:50.758136  6481 raft_consensus.cc:385] T 00000000000000000000000000000000 P d972c1d6536644749f69b33d4a3cb111 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:50.758184  6481 raft_consensus.cc:740] T 00000000000000000000000000000000 P d972c1d6536644749f69b33d4a3cb111 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: d972c1d6536644749f69b33d4a3cb111, State: Initialized, Role: FOLLOWER
I20260812 06:18:50.759073  6481 consensus_queue.cc:260] T 00000000000000000000000000000000 P d972c1d6536644749f69b33d4a3cb111 [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: "d972c1d6536644749f69b33d4a3cb111" member_type: VOTER }
I20260812 06:18:50.759290  6481 raft_consensus.cc:399] T 00000000000000000000000000000000 P d972c1d6536644749f69b33d4a3cb111 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:50.759402  6481 raft_consensus.cc:493] T 00000000000000000000000000000000 P d972c1d6536644749f69b33d4a3cb111 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:50.759567  6481 raft_consensus.cc:3060] T 00000000000000000000000000000000 P d972c1d6536644749f69b33d4a3cb111 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:50.760602  6481 raft_consensus.cc:515] T 00000000000000000000000000000000 P d972c1d6536644749f69b33d4a3cb111 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d972c1d6536644749f69b33d4a3cb111" member_type: VOTER }
I20260812 06:18:50.761236  6481 leader_election.cc:304] T 00000000000000000000000000000000 P d972c1d6536644749f69b33d4a3cb111 [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: d972c1d6536644749f69b33d4a3cb111; no voters: 
I20260812 06:18:50.761683  6481 leader_election.cc:290] T 00000000000000000000000000000000 P d972c1d6536644749f69b33d4a3cb111 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:50.762099  6484 raft_consensus.cc:2804] T 00000000000000000000000000000000 P d972c1d6536644749f69b33d4a3cb111 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:50.762779  6484 raft_consensus.cc:697] T 00000000000000000000000000000000 P d972c1d6536644749f69b33d4a3cb111 [term 1 LEADER]: Becoming Leader. State: Replica: d972c1d6536644749f69b33d4a3cb111, State: Running, Role: LEADER
I20260812 06:18:50.763288  6481 sys_catalog.cc:565] T 00000000000000000000000000000000 P d972c1d6536644749f69b33d4a3cb111 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:50.763443  6484 consensus_queue.cc:237] T 00000000000000000000000000000000 P d972c1d6536644749f69b33d4a3cb111 [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: "d972c1d6536644749f69b33d4a3cb111" member_type: VOTER }
I20260812 06:18:50.766484  6406 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:50.766443  6485 sys_catalog.cc:455] T 00000000000000000000000000000000 P d972c1d6536644749f69b33d4a3cb111 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "d972c1d6536644749f69b33d4a3cb111" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d972c1d6536644749f69b33d4a3cb111" member_type: VOTER } }
I20260812 06:18:50.766449  6486 sys_catalog.cc:455] T 00000000000000000000000000000000 P d972c1d6536644749f69b33d4a3cb111 [sys.catalog]: SysCatalogTable state changed. Reason: New leader d972c1d6536644749f69b33d4a3cb111. Latest consensus state: current_term: 1 leader_uuid: "d972c1d6536644749f69b33d4a3cb111" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d972c1d6536644749f69b33d4a3cb111" member_type: VOTER } }
I20260812 06:18:50.766705  6486 sys_catalog.cc:458] T 00000000000000000000000000000000 P d972c1d6536644749f69b33d4a3cb111 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:50.766705  6485 sys_catalog.cc:458] T 00000000000000000000000000000000 P d972c1d6536644749f69b33d4a3cb111 [sys.catalog]: This master's current role is: LEADER
W20260812 06:18:50.769819  6499 catalog_manager.cc:1594] T 00000000000000000000000000000000 P d972c1d6536644749f69b33d4a3cb111: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:18:50.769989  6499 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:18:50.770154  6501 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:50.771270  6501 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:50.778592  6501 catalog_manager.cc:1383] Generated new cluster ID: b28e91c4eb824437ab796f41e191da2c
I20260812 06:18:50.778704  6501 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:50.807453  6501 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:50.809394  6501 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:50.822530  6501 catalog_manager.cc:6092] T 00000000000000000000000000000000 P d972c1d6536644749f69b33d4a3cb111: Generated new TSK 0
I20260812 06:18:50.824402  6501 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:50.832491  6406 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:50.835878  6508 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:50.836073  6505 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:50.836246  6406 server_base.cc:1061] running on GCE node
W20260812 06:18:50.836114  6506 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:50.836642  6406 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:50.836728  6406 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:50.836758  6406 hybrid_clock.cc:648] HybridClock initialized: now 1786515530836757 us; error 0 us; skew 500 ppm
I20260812 06:18:50.838085  6406 webserver.cc:533] Webserver started at http://127.6.65.129:44861/ using document root <none> and password file <none>
I20260812 06:18:50.838315  6406 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:50.838423  6406 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:50.838523  6406 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:50.839087  6406 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515530638234-6406-0/minicluster-data/ts-0-root/instance:
uuid: "5d098571a3ad434ab5676d529656ac4d"
format_stamp: "Formatted at 2026-08-12 06:18:50 on dist-test-slave-77v9"
I20260812 06:18:50.842221  6406 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.000s	sys 0.003s
I20260812 06:18:50.843650  6513 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:50.844053  6406 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:50.844148  6406 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515530638234-6406-0/minicluster-data/ts-0-root
uuid: "5d098571a3ad434ab5676d529656ac4d"
format_stamp: "Formatted at 2026-08-12 06:18:50 on dist-test-slave-77v9"
I20260812 06:18:50.844259  6406 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515530638234-6406-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515530638234-6406-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515530638234-6406-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:50.863909  6406 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:50.864593  6406 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:50.865383  6406 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:50.866526  6406 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:50.866618  6406 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:50.866715  6406 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:50.866763  6406 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:50.875278  6406 rpc_server.cc:307] RPC server started. Bound to: 127.6.65.129:41613
I20260812 06:18:50.875310  6584 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.6.65.129:41613 every 8 connection(s)
I20260812 06:18:50.889084  6585 heartbeater.cc:344] Connected to a master server at 127.6.65.190:45307
I20260812 06:18:50.889451  6585 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:50.890126  6585 heartbeater.cc:507] Master 127.6.65.190:45307 requested a full tablet report, sending...
I20260812 06:18:50.893134  6440 ts_manager.cc:194] Registered new tserver with Master: 5d098571a3ad434ab5676d529656ac4d (127.6.65.129:41613)
I20260812 06:18:50.893666  6406 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.017510789s
I20260812 06:18:50.895311  6440 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:34714
I20260812 06:18:50.908756  6440 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:34722:
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:50.929061  6545 tablet_service.cc:1511] Processing CreateTablet for tablet a07445f526134d54b4316e8c62220bcf (DEFAULT_TABLE table=heavy-update-compaction-test [id=b9d411920c0f410f95926a8eedad8c47]), partition=
I20260812 06:18:50.929662  6545 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet a07445f526134d54b4316e8c62220bcf. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:50.933034  6597 tablet_bootstrap.cc:492] T a07445f526134d54b4316e8c62220bcf P 5d098571a3ad434ab5676d529656ac4d: Bootstrap starting.
I20260812 06:18:50.934362  6597 tablet_bootstrap.cc:654] T a07445f526134d54b4316e8c62220bcf P 5d098571a3ad434ab5676d529656ac4d: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:50.936810  6597 tablet_bootstrap.cc:492] T a07445f526134d54b4316e8c62220bcf P 5d098571a3ad434ab5676d529656ac4d: No bootstrap required, opened a new log
I20260812 06:18:50.937155  6597 ts_tablet_manager.cc:1403] T a07445f526134d54b4316e8c62220bcf P 5d098571a3ad434ab5676d529656ac4d: Time spent bootstrapping tablet: real 0.004s	user 0.003s	sys 0.001s
I20260812 06:18:50.937820  6597 raft_consensus.cc:359] T a07445f526134d54b4316e8c62220bcf P 5d098571a3ad434ab5676d529656ac4d [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5d098571a3ad434ab5676d529656ac4d" member_type: VOTER last_known_addr { host: "127.6.65.129" port: 41613 } }
I20260812 06:18:50.938001  6597 raft_consensus.cc:385] T a07445f526134d54b4316e8c62220bcf P 5d098571a3ad434ab5676d529656ac4d [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:50.938060  6597 raft_consensus.cc:740] T a07445f526134d54b4316e8c62220bcf P 5d098571a3ad434ab5676d529656ac4d [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 5d098571a3ad434ab5676d529656ac4d, State: Initialized, Role: FOLLOWER
I20260812 06:18:50.938336  6597 consensus_queue.cc:260] T a07445f526134d54b4316e8c62220bcf P 5d098571a3ad434ab5676d529656ac4d [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: "5d098571a3ad434ab5676d529656ac4d" member_type: VOTER last_known_addr { host: "127.6.65.129" port: 41613 } }
I20260812 06:18:50.938478  6597 raft_consensus.cc:399] T a07445f526134d54b4316e8c62220bcf P 5d098571a3ad434ab5676d529656ac4d [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:50.938573  6597 raft_consensus.cc:493] T a07445f526134d54b4316e8c62220bcf P 5d098571a3ad434ab5676d529656ac4d [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:50.938645  6597 raft_consensus.cc:3060] T a07445f526134d54b4316e8c62220bcf P 5d098571a3ad434ab5676d529656ac4d [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:50.939683  6597 raft_consensus.cc:515] T a07445f526134d54b4316e8c62220bcf P 5d098571a3ad434ab5676d529656ac4d [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5d098571a3ad434ab5676d529656ac4d" member_type: VOTER last_known_addr { host: "127.6.65.129" port: 41613 } }
I20260812 06:18:50.939908  6597 leader_election.cc:304] T a07445f526134d54b4316e8c62220bcf P 5d098571a3ad434ab5676d529656ac4d [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: 5d098571a3ad434ab5676d529656ac4d; no voters: 
I20260812 06:18:50.940222  6597 leader_election.cc:290] T a07445f526134d54b4316e8c62220bcf P 5d098571a3ad434ab5676d529656ac4d [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:50.940461  6600 raft_consensus.cc:2804] T a07445f526134d54b4316e8c62220bcf P 5d098571a3ad434ab5676d529656ac4d [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:50.940781  6597 ts_tablet_manager.cc:1434] T a07445f526134d54b4316e8c62220bcf P 5d098571a3ad434ab5676d529656ac4d: Time spent starting tablet: real 0.004s	user 0.001s	sys 0.003s
I20260812 06:18:50.941287  6585 heartbeater.cc:499] Master 127.6.65.190:45307 was elected leader, sending a full tablet report...
I20260812 06:18:50.940869  6600 raft_consensus.cc:697] T a07445f526134d54b4316e8c62220bcf P 5d098571a3ad434ab5676d529656ac4d [term 1 LEADER]: Becoming Leader. State: Replica: 5d098571a3ad434ab5676d529656ac4d, State: Running, Role: LEADER
I20260812 06:18:50.942821  6600 consensus_queue.cc:237] T a07445f526134d54b4316e8c62220bcf P 5d098571a3ad434ab5676d529656ac4d [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: "5d098571a3ad434ab5676d529656ac4d" member_type: VOTER last_known_addr { host: "127.6.65.129" port: 41613 } }
I20260812 06:18:50.948125  6440 catalog_manager.cc:5719] T a07445f526134d54b4316e8c62220bcf P 5d098571a3ad434ab5676d529656ac4d reported cstate change: term changed from 0 to 1, leader changed from <none> to 5d098571a3ad434ab5676d529656ac4d (127.6.65.129). New cstate: current_term: 1 leader_uuid: "5d098571a3ad434ab5676d529656ac4d" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5d098571a3ad434ab5676d529656ac4d" member_type: VOTER last_known_addr { host: "127.6.65.129" port: 41613 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:51.033306  6406 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.073s	user 0.024s	sys 0.008s
I20260812 06:18:51.126895  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling FlushMRSOp(a07445f526134d54b4316e8c62220bcf): perf score=10.125253
I20260812 06:18:51.292488  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: FlushMRSOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.165s	user 0.128s	sys 0.027s Metrics: {"bytes_written":8205078,"cfile_init":1,"compiler_manager_pool.queue_time_us":298,"delete_count":0,"dirs.queue_time_us":101,"dirs.run_cpu_time_us":262,"dirs.run_wall_time_us":1296,"drs_written":1,"lbm_read_time_us":137,"lbm_reads_lt_1ms":4,"lbm_write_time_us":34700,"lbm_writes_lt_1ms":457,"peak_mem_usage":0,"reinsert_count":0,"rows_written":102,"thread_start_us":164,"threads_started":1,"update_count":1000}
I20260812 06:18:51.294417  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling LogGCOp(a07445f526134d54b4316e8c62220bcf): free 8725963 bytes of WAL
I20260812 06:18:51.295032  6519 log_reader.cc:385] T a07445f526134d54b4316e8c62220bcf: removed 1 log segments from log reader
I20260812 06:18:51.295954  6519 log.cc:1079] T a07445f526134d54b4316e8c62220bcf P 5d098571a3ad434ab5676d529656ac4d: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/a07445f526134d54b4316e8c62220bcf/wal-000000001 (ops 1-6)
I20260812 06:18:51.298807  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: LogGCOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.004s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:18:51.299516  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf): perf score=2.188937
I20260812 06:18:51.316393  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.017s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6428,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:51.317085  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling MajorDeltaCompactionOp(a07445f526134d54b4316e8c62220bcf): perf score=1.000000
I20260812 06:18:51.465221  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: MajorDeltaCompactionOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.148s	user 0.117s	sys 0.030s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16487935,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":824,"lbm_read_time_us":9358,"lbm_reads_lt_1ms":364,"lbm_write_time_us":24710,"lbm_writes_lt_1ms":343,"peak_mem_usage":38262756,"reinsert_count":0,"thread_start_us":479,"threads_started":5,"update_count":1500}
I20260812 06:18:51.466022  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf): perf score=8.142062
I20260812 06:18:51.505131  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.039s	user 0.016s	sys 0.022s Metrics: {"bytes_written":9640924,"delete_count":0,"lbm_write_time_us":16614,"lbm_writes_lt_1ms":238,"reinsert_count":0,"update_count":1175}
I20260812 06:18:51.505743  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling UndoDeltaBlockGCOp(a07445f526134d54b4316e8c62220bcf): 8206537 bytes on disk
I20260812 06:18:51.506351  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: UndoDeltaBlockGCOp(a07445f526134d54b4316e8c62220bcf) 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:51.506910  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf): perf score=1.196750
I20260812 06:18:51.518679  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.012s	user 0.001s	sys 0.008s Metrics: {"bytes_written":2666779,"delete_count":0,"lbm_write_time_us":3784,"lbm_writes_lt_1ms":68,"reinsert_count":0,"update_count":325}
I20260812 06:18:51.519328  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling MajorDeltaCompactionOp(a07445f526134d54b4316e8c62220bcf): perf score=1.000000
I20260812 06:18:51.682574  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: MajorDeltaCompactionOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.163s	user 0.117s	sys 0.032s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16487901,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1189,"lbm_read_time_us":12556,"lbm_reads_lt_1ms":364,"lbm_write_time_us":24536,"lbm_writes_lt_1ms":343,"mutex_wait_us":33,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":10632192,"update_count":1500}
I20260812 06:18:51.686123  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf): perf score=10.126437
I20260812 06:18:51.737516  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.051s	user 0.032s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19160,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:51.738140  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf): perf score=2.188937
I20260812 06:18:51.751649  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102663,"delete_count":0,"lbm_write_time_us":4863,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:51.752269  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling MajorDeltaCompactionOp(a07445f526134d54b4316e8c62220bcf): perf score=1.000000
I20260812 06:18:51.909850  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: MajorDeltaCompactionOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.157s	user 0.113s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590351,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":331,"lbm_read_time_us":9647,"lbm_reads_lt_1ms":472,"lbm_write_time_us":30330,"lbm_writes_lt_1ms":443,"mutex_wait_us":109,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":19328,"update_count":2000}
I20260812 06:18:51.910681  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf): perf score=10.126437
I20260812 06:18:51.953962  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.043s	user 0.015s	sys 0.024s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18311,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:51.954730  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling MajorDeltaCompactionOp(a07445f526134d54b4316e8c62220bcf): perf score=1.000000
I20260812 06:18:52.080394  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: MajorDeltaCompactionOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.125s	user 0.101s	sys 0.024s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16487817,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":447,"lbm_read_time_us":9560,"lbm_reads_lt_1ms":363,"lbm_write_time_us":24115,"lbm_writes_lt_1ms":343,"mutex_wait_us":44,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":21760,"update_count":1500}
I20260812 06:18:52.081184  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf): perf score=10.126437
I20260812 06:18:52.134374  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.053s	user 0.027s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17411,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:52.135138  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf): perf score=2.188937
I20260812 06:18:52.150524  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.015s	user 0.009s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5796,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:52.151046  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling MajorDeltaCompactionOp(a07445f526134d54b4316e8c62220bcf): perf score=1.000000
I20260812 06:18:52.290871  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: MajorDeltaCompactionOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.140s	user 0.098s	sys 0.041s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590347,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":763,"lbm_read_time_us":11265,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26420,"lbm_writes_lt_1ms":443,"mutex_wait_us":318,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3712,"update_count":2000}
I20260812 06:18:52.291574  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf): perf score=10.126437
I20260812 06:18:52.342415  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.051s	user 0.023s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19284,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:52.343178  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf): perf score=2.188937
I20260812 06:18:52.355813  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4741,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:52.356729  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling MajorDeltaCompactionOp(a07445f526134d54b4316e8c62220bcf): perf score=1.000000
I20260812 06:18:52.501015  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: MajorDeltaCompactionOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.144s	user 0.121s	sys 0.023s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590347,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1089,"lbm_read_time_us":9159,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29158,"lbm_writes_lt_1ms":443,"mutex_wait_us":467,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":945536,"update_count":2000}
I20260812 06:18:52.501789  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf): perf score=10.126437
I20260812 06:18:52.560225  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.058s	user 0.022s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":33672,"lbm_writes_1-10_ms":1,"lbm_writes_10-100_ms":1,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:18:52.561015  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf): perf score=2.188937
I20260812 06:18:52.574368  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.013s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5130,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:52.574875  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling MajorDeltaCompactionOp(a07445f526134d54b4316e8c62220bcf): perf score=1.000000
I20260812 06:18:52.714290  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: MajorDeltaCompactionOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.139s	user 0.107s	sys 0.031s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590346,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":2238,"lbm_read_time_us":10299,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28198,"lbm_writes_lt_1ms":443,"mutex_wait_us":397,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":18432,"update_count":2000}
I20260812 06:18:52.717411  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf): perf score=10.126437
I20260812 06:18:52.775607  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.058s	user 0.017s	sys 0.036s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18683,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:52.776650  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf): perf score=2.188937
I20260812 06:18:52.792511  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.016s	user 0.008s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5739,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:52.793321  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling FlushMRSOp(a07445f526134d54b4316e8c62220bcf): perf score=1.000000
I20260812 06:18:52.843189  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: FlushMRSOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.050s	user 0.039s	sys 0.000s Metrics: {"bytes_written":1193504,"cfile_init":1,"dirs.queue_time_us":123,"dirs.run_cpu_time_us":302,"dirs.run_wall_time_us":1898,"drs_written":1,"lbm_read_time_us":73,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2449,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:52.844298  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling LogGCOp(a07445f526134d54b4316e8c62220bcf): free 115943180 bytes of WAL
I20260812 06:18:52.844589  6519 log_reader.cc:385] T a07445f526134d54b4316e8c62220bcf: removed 11 log segments from log reader
I20260812 06:18:52.844638  6519 log.cc:1079] T a07445f526134d54b4316e8c62220bcf P 5d098571a3ad434ab5676d529656ac4d: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/a07445f526134d54b4316e8c62220bcf/wal-000000002 (ops 7-11)
I20260812 06:18:52.844676  6519 log.cc:1079] T a07445f526134d54b4316e8c62220bcf P 5d098571a3ad434ab5676d529656ac4d: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/a07445f526134d54b4316e8c62220bcf/wal-000000003 (ops 12-16)
I20260812 06:18:52.844756  6519 log.cc:1079] T a07445f526134d54b4316e8c62220bcf P 5d098571a3ad434ab5676d529656ac4d: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/a07445f526134d54b4316e8c62220bcf/wal-000000004 (ops 17-21)
I20260812 06:18:52.844856  6519 log.cc:1079] T a07445f526134d54b4316e8c62220bcf P 5d098571a3ad434ab5676d529656ac4d: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/a07445f526134d54b4316e8c62220bcf/wal-000000005 (ops 22-26)
I20260812 06:18:52.844909  6519 log.cc:1079] T a07445f526134d54b4316e8c62220bcf P 5d098571a3ad434ab5676d529656ac4d: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/a07445f526134d54b4316e8c62220bcf/wal-000000006 (ops 27-31)
I20260812 06:18:52.844954  6519 log.cc:1079] T a07445f526134d54b4316e8c62220bcf P 5d098571a3ad434ab5676d529656ac4d: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/a07445f526134d54b4316e8c62220bcf/wal-000000007 (ops 32-36)
I20260812 06:18:52.845001  6519 log.cc:1079] T a07445f526134d54b4316e8c62220bcf P 5d098571a3ad434ab5676d529656ac4d: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/a07445f526134d54b4316e8c62220bcf/wal-000000008 (ops 37-41)
I20260812 06:18:52.845050  6519 log.cc:1079] T a07445f526134d54b4316e8c62220bcf P 5d098571a3ad434ab5676d529656ac4d: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/a07445f526134d54b4316e8c62220bcf/wal-000000009 (ops 42-46)
I20260812 06:18:52.845093  6519 log.cc:1079] T a07445f526134d54b4316e8c62220bcf P 5d098571a3ad434ab5676d529656ac4d: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/a07445f526134d54b4316e8c62220bcf/wal-000000010 (ops 47-51)
I20260812 06:18:52.845144  6519 log.cc:1079] T a07445f526134d54b4316e8c62220bcf P 5d098571a3ad434ab5676d529656ac4d: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/a07445f526134d54b4316e8c62220bcf/wal-000000011 (ops 52-56)
I20260812 06:18:52.845182  6519 log.cc:1079] T a07445f526134d54b4316e8c62220bcf P 5d098571a3ad434ab5676d529656ac4d: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/a07445f526134d54b4316e8c62220bcf/wal-000000012 (ops 57-61)
I20260812 06:18:52.878123  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: LogGCOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.034s	user 0.000s	sys 0.032s Metrics: {}
I20260812 06:18:52.878662  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling UndoDeltaBlockGCOp(a07445f526134d54b4316e8c62220bcf): 466 bytes on disk
I20260812 06:18:52.879163  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: UndoDeltaBlockGCOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":69,"lbm_reads_lt_1ms":4}
I20260812 06:18:52.879703  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf): perf score=3.181125
I20260812 06:18:52.900075  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.020s	user 0.000s	sys 0.012s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":5748,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:52.900691  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf): perf score=2.188937
I20260812 06:18:52.911408  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.010s	user 0.002s	sys 0.006s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3878,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:52.911965  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling MajorDeltaCompactionOp(a07445f526134d54b4316e8c62220bcf): perf score=1.000000
I20260812 06:18:53.169461  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: MajorDeltaCompactionOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.257s	user 0.179s	sys 0.067s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28795398,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":4029,"lbm_read_time_us":17214,"lbm_reads_lt_1ms":674,"lbm_write_time_us":39999,"lbm_writes_lt_1ms":643,"mutex_wait_us":1920,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":23168,"thread_start_us":113,"threads_started":1,"update_count":3000}
I20260812 06:18:53.170238  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf): perf score=14.095187
I20260812 06:18:53.222379  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.052s	user 0.035s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22759,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:53.223601  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling MajorDeltaCompactionOp(a07445f526134d54b4316e8c62220bcf): perf score=1.000000
I20260812 06:18:53.420459  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: MajorDeltaCompactionOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.197s	user 0.126s	sys 0.057s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20590227,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":257,"lbm_read_time_us":12488,"lbm_reads_lt_1ms":467,"lbm_write_time_us":31003,"lbm_writes_lt_1ms":443,"mutex_wait_us":74,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":492416,"update_count":2000}
I20260812 06:18:53.421365  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf): perf score=14.095187
I20260812 06:18:53.487411  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.066s	user 0.036s	sys 0.020s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":25402,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:53.488543  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf): perf score=2.188937
I20260812 06:18:53.505621  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.017s	user 0.011s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6588,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:53.506419  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling MajorDeltaCompactionOp(a07445f526134d54b4316e8c62220bcf): perf score=1.000000
I20260812 06:18:53.737375  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: MajorDeltaCompactionOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.231s	user 0.144s	sys 0.067s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24692760,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":338,"lbm_read_time_us":14393,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34907,"lbm_writes_lt_1ms":543,"mutex_wait_us":84,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":18688,"update_count":2500}
I20260812 06:18:53.738178  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf): perf score=14.095187
I20260812 06:18:53.804137  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.066s	user 0.010s	sys 0.048s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":28459,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:18:53.804941  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf): perf score=2.188937
I20260812 06:18:53.819265  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5325,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:53.819762  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling MajorDeltaCompactionOp(a07445f526134d54b4316e8c62220bcf): perf score=1.000000
I20260812 06:18:53.993180  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: MajorDeltaCompactionOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.173s	user 0.128s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24692758,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":554,"lbm_read_time_us":12619,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33488,"lbm_writes_lt_1ms":543,"mutex_wait_us":25,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13568,"update_count":2500}
I20260812 06:18:53.994045  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf): perf score=10.126437
I20260812 06:18:54.038199  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.044s	user 0.034s	sys 0.009s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18571,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:54.039176  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf): perf score=2.188937
I20260812 06:18:54.059921  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.020s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7167,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:54.060532  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling MajorDeltaCompactionOp(a07445f526134d54b4316e8c62220bcf): perf score=1.000000
I20260812 06:18:54.219760  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: MajorDeltaCompactionOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.159s	user 0.119s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590347,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":190,"lbm_read_time_us":11990,"lbm_reads_lt_1ms":464,"lbm_write_time_us":31419,"lbm_writes_lt_1ms":443,"mutex_wait_us":53,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14336,"update_count":2000}
I20260812 06:18:54.220623  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf): perf score=10.126437
I20260812 06:18:54.275473  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.054s	user 0.032s	sys 0.013s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":21123,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:54.276244  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf): perf score=2.188937
I20260812 06:18:54.289626  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.013s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4879,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:54.290378  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling MajorDeltaCompactionOp(a07445f526134d54b4316e8c62220bcf): perf score=1.000000
I20260812 06:18:54.441784  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: MajorDeltaCompactionOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.151s	user 0.122s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590348,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":438,"lbm_read_time_us":11299,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28849,"lbm_writes_lt_1ms":443,"mutex_wait_us":81,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":90496,"update_count":2000}
I20260812 06:18:54.442601  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf): perf score=10.126437
I20260812 06:18:54.508280  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.065s	user 0.032s	sys 0.020s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":19623,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:54.509045  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf): perf score=2.188937
I20260812 06:18:54.521886  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.013s	user 0.006s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5028,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:54.522542  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling FlushMRSOp(a07445f526134d54b4316e8c62220bcf): perf score=1.000000
I20260812 06:18:54.573392  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: FlushMRSOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.051s	user 0.036s	sys 0.001s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":95,"dirs.run_cpu_time_us":344,"dirs.run_wall_time_us":2003,"drs_written":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1747,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:54.574288  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling LogGCOp(a07445f526134d54b4316e8c62220bcf): free 120553382 bytes of WAL
I20260812 06:18:54.574564  6519 log_reader.cc:385] T a07445f526134d54b4316e8c62220bcf: removed 12 log segments from log reader
I20260812 06:18:54.574609  6519 log.cc:1079] T a07445f526134d54b4316e8c62220bcf P 5d098571a3ad434ab5676d529656ac4d: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/a07445f526134d54b4316e8c62220bcf/wal-000000013 (ops 62-66)
I20260812 06:18:54.574667  6519 log.cc:1079] T a07445f526134d54b4316e8c62220bcf P 5d098571a3ad434ab5676d529656ac4d: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/a07445f526134d54b4316e8c62220bcf/wal-000000014 (ops 67-71)
I20260812 06:18:54.574714  6519 log.cc:1079] T a07445f526134d54b4316e8c62220bcf P 5d098571a3ad434ab5676d529656ac4d: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/a07445f526134d54b4316e8c62220bcf/wal-000000015 (ops 72-76)
I20260812 06:18:54.574757  6519 log.cc:1079] T a07445f526134d54b4316e8c62220bcf P 5d098571a3ad434ab5676d529656ac4d: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/a07445f526134d54b4316e8c62220bcf/wal-000000016 (ops 77-80)
I20260812 06:18:54.574797  6519 log.cc:1079] T a07445f526134d54b4316e8c62220bcf P 5d098571a3ad434ab5676d529656ac4d: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/a07445f526134d54b4316e8c62220bcf/wal-000000017 (ops 81-85)
I20260812 06:18:54.574837  6519 log.cc:1079] T a07445f526134d54b4316e8c62220bcf P 5d098571a3ad434ab5676d529656ac4d: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/a07445f526134d54b4316e8c62220bcf/wal-000000018 (ops 86-90)
I20260812 06:18:54.574884  6519 log.cc:1079] T a07445f526134d54b4316e8c62220bcf P 5d098571a3ad434ab5676d529656ac4d: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/a07445f526134d54b4316e8c62220bcf/wal-000000019 (ops 91-95)
I20260812 06:18:54.574925  6519 log.cc:1079] T a07445f526134d54b4316e8c62220bcf P 5d098571a3ad434ab5676d529656ac4d: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/a07445f526134d54b4316e8c62220bcf/wal-000000020 (ops 96-100)
I20260812 06:18:54.574966  6519 log.cc:1079] T a07445f526134d54b4316e8c62220bcf P 5d098571a3ad434ab5676d529656ac4d: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/a07445f526134d54b4316e8c62220bcf/wal-000000021 (ops 101-104)
I20260812 06:18:54.575006  6519 log.cc:1079] T a07445f526134d54b4316e8c62220bcf P 5d098571a3ad434ab5676d529656ac4d: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/a07445f526134d54b4316e8c62220bcf/wal-000000022 (ops 105-109)
I20260812 06:18:54.575047  6519 log.cc:1079] T a07445f526134d54b4316e8c62220bcf P 5d098571a3ad434ab5676d529656ac4d: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/a07445f526134d54b4316e8c62220bcf/wal-000000023 (ops 110-114)
I20260812 06:18:54.575089  6519 log.cc:1079] T a07445f526134d54b4316e8c62220bcf P 5d098571a3ad434ab5676d529656ac4d: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/a07445f526134d54b4316e8c62220bcf/wal-000000024 (ops 115-119)
I20260812 06:18:54.604125  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: LogGCOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.030s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:18:54.604871  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf): perf score=3.181125
I20260812 06:18:54.632238  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.027s	user 0.006s	sys 0.009s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":7375,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:54.632995  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf): perf score=2.188937
I20260812 06:18:54.649283  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.016s	user 0.012s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5655,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:54.650349  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling UndoDeltaBlockGCOp(a07445f526134d54b4316e8c62220bcf): 448 bytes on disk
I20260812 06:18:54.651144  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: UndoDeltaBlockGCOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":145,"lbm_reads_lt_1ms":4}
I20260812 06:18:54.651975  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling MajorDeltaCompactionOp(a07445f526134d54b4316e8c62220bcf): perf score=1.000000
I20260812 06:18:54.909619  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: MajorDeltaCompactionOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.257s	user 0.183s	sys 0.071s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28795401,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":805,"lbm_read_time_us":15159,"lbm_reads_lt_1ms":674,"lbm_write_time_us":43802,"lbm_writes_lt_1ms":643,"mutex_wait_us":82,"peak_mem_usage":75542472,"reinsert_count":0,"thread_start_us":127,"threads_started":1,"update_count":3000}
I20260812 06:18:54.911571  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf): perf score=14.095187
I20260812 06:18:54.973057  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.061s	user 0.052s	sys 0.007s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":26657,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:54.973861  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling MajorDeltaCompactionOp(a07445f526134d54b4316e8c62220bcf): perf score=1.000000
I20260812 06:18:55.147572  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: MajorDeltaCompactionOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.173s	user 0.122s	sys 0.051s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20590228,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":418,"lbm_read_time_us":12152,"lbm_reads_lt_1ms":463,"lbm_write_time_us":29840,"lbm_writes_lt_1ms":443,"mutex_wait_us":34,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14848,"update_count":2000}
I20260812 06:18:55.148464  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf): perf score=10.126437
I20260812 06:18:55.186982  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.038s	user 0.024s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16732,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:55.187773  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf): perf score=2.188937
I20260812 06:18:55.208750  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.021s	user 0.019s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":8415,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:55.210649  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling MajorDeltaCompactionOp(a07445f526134d54b4316e8c62220bcf): perf score=1.000000
I20260812 06:18:55.371819  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: MajorDeltaCompactionOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.161s	user 0.117s	sys 0.041s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590347,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1806,"lbm_read_time_us":10872,"lbm_reads_lt_1ms":464,"lbm_write_time_us":30589,"lbm_writes_lt_1ms":443,"mutex_wait_us":69,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:18:55.372642  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf): perf score=10.126437
I20260812 06:18:55.421861  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.049s	user 0.033s	sys 0.011s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":19791,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:55.422739  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf): perf score=2.188937
I20260812 06:18:55.443116  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.020s	user 0.009s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7760,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:55.443961  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling MajorDeltaCompactionOp(a07445f526134d54b4316e8c62220bcf): perf score=1.000000
I20260812 06:18:55.605510  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: MajorDeltaCompactionOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.161s	user 0.129s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590348,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":106,"lbm_read_time_us":13152,"lbm_reads_lt_1ms":464,"lbm_write_time_us":28872,"lbm_writes_lt_1ms":443,"mutex_wait_us":40,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":36352,"update_count":2000}
I20260812 06:18:55.606140  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf): perf score=10.126437
I20260812 06:18:55.658738  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.052s	user 0.022s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19716,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:55.659433  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf): perf score=2.188937
I20260812 06:18:55.671741  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.012s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4720,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:55.672319  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling MajorDeltaCompactionOp(a07445f526134d54b4316e8c62220bcf): perf score=1.000000
I20260812 06:18:55.836447  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: MajorDeltaCompactionOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.164s	user 0.111s	sys 0.047s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590347,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1120,"dirs.run_cpu_time_us":1096,"dirs.run_wall_time_us":5031,"lbm_read_time_us":9562,"lbm_reads_lt_1ms":472,"lbm_write_time_us":31779,"lbm_writes_lt_1ms":443,"mutex_wait_us":355,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":55680,"update_count":2000}
I20260812 06:18:55.837738  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf): perf score=10.126437
I20260812 06:18:55.895596  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.057s	user 0.022s	sys 0.031s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":19252,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:55.896322  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf): perf score=2.188937
I20260812 06:18:55.913002  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.016s	user 0.013s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6219,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:55.913923  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling MajorDeltaCompactionOp(a07445f526134d54b4316e8c62220bcf): perf score=1.000000
I20260812 06:18:56.164916  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: MajorDeltaCompactionOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.251s	user 0.166s	sys 0.075s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590348,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1625,"lbm_read_time_us":14373,"lbm_reads_lt_1ms":472,"lbm_write_time_us":37219,"lbm_writes_lt_1ms":443,"mutex_wait_us":1266,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":19328,"update_count":2000}
I20260812 06:18:56.165832  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf): perf score=14.095187
I20260812 06:18:56.243013  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.077s	user 0.065s	sys 0.007s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":35008,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:56.243892  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf): perf score=2.188937
I20260812 06:18:56.263994  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.020s	user 0.017s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7678,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:56.265033  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling MajorDeltaCompactionOp(a07445f526134d54b4316e8c62220bcf): perf score=1.000000
I20260812 06:18:56.596578  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: MajorDeltaCompactionOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.331s	user 0.257s	sys 0.054s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24692758,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1991,"lbm_read_time_us":19996,"lbm_reads_lt_1ms":572,"lbm_write_time_us":56841,"lbm_writes_lt_1ms":543,"mutex_wait_us":1,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:56.597681  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf): perf score=22.032687
I20260812 06:18:56.681191  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.083s	user 0.042s	sys 0.040s Metrics: {"bytes_written":24614723,"delete_count":0,"lbm_write_time_us":36592,"lbm_writes_lt_1ms":603,"reinsert_count":0,"update_count":3000}
I20260812 06:18:56.681949  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf): perf score=2.188937
I20260812 06:18:56.719229  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.037s	user 0.018s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":8298,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:56.719878  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf): perf score=2.188937
I20260812 06:18:56.733152  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.013s	user 0.006s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4816,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:56.733871  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling FlushMRSOp(a07445f526134d54b4316e8c62220bcf): perf score=1.000000
I20260812 06:18:56.784641  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: FlushMRSOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.051s	user 0.036s	sys 0.004s Metrics: {"bytes_written":1439527,"cfile_init":1,"dirs.queue_time_us":182,"dirs.run_cpu_time_us":449,"dirs.run_wall_time_us":1971,"drs_written":1,"lbm_read_time_us":77,"lbm_reads_lt_1ms":4,"lbm_write_time_us":3090,"lbm_writes_lt_1ms":44,"peak_mem_usage":0,"rows_written":35}
I20260812 06:18:56.786072  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling LogGCOp(a07445f526134d54b4316e8c62220bcf): free 145042560 bytes of WAL
I20260812 06:18:56.786679  6519 log_reader.cc:385] T a07445f526134d54b4316e8c62220bcf: removed 14 log segments from log reader
I20260812 06:18:56.786866  6519 log.cc:1079] T a07445f526134d54b4316e8c62220bcf P 5d098571a3ad434ab5676d529656ac4d: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/a07445f526134d54b4316e8c62220bcf/wal-000000025 (ops 120-124)
I20260812 06:18:56.786952  6519 log.cc:1079] T a07445f526134d54b4316e8c62220bcf P 5d098571a3ad434ab5676d529656ac4d: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/a07445f526134d54b4316e8c62220bcf/wal-000000026 (ops 125-128)
I20260812 06:18:56.787005  6519 log.cc:1079] T a07445f526134d54b4316e8c62220bcf P 5d098571a3ad434ab5676d529656ac4d: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/a07445f526134d54b4316e8c62220bcf/wal-000000027 (ops 129-133)
I20260812 06:18:56.787034  6519 log.cc:1079] T a07445f526134d54b4316e8c62220bcf P 5d098571a3ad434ab5676d529656ac4d: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/a07445f526134d54b4316e8c62220bcf/wal-000000028 (ops 134-138)
I20260812 06:18:56.787058  6519 log.cc:1079] T a07445f526134d54b4316e8c62220bcf P 5d098571a3ad434ab5676d529656ac4d: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/a07445f526134d54b4316e8c62220bcf/wal-000000029 (ops 139-143)
I20260812 06:18:56.787200  6519 log.cc:1079] T a07445f526134d54b4316e8c62220bcf P 5d098571a3ad434ab5676d529656ac4d: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/a07445f526134d54b4316e8c62220bcf/wal-000000030 (ops 144-148)
I20260812 06:18:56.787248  6519 log.cc:1079] T a07445f526134d54b4316e8c62220bcf P 5d098571a3ad434ab5676d529656ac4d: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/a07445f526134d54b4316e8c62220bcf/wal-000000031 (ops 149-153)
I20260812 06:18:56.787288  6519 log.cc:1079] T a07445f526134d54b4316e8c62220bcf P 5d098571a3ad434ab5676d529656ac4d: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/a07445f526134d54b4316e8c62220bcf/wal-000000032 (ops 154-158)
I20260812 06:18:56.787328  6519 log.cc:1079] T a07445f526134d54b4316e8c62220bcf P 5d098571a3ad434ab5676d529656ac4d: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/a07445f526134d54b4316e8c62220bcf/wal-000000033 (ops 159-163)
I20260812 06:18:56.787372  6519 log.cc:1079] T a07445f526134d54b4316e8c62220bcf P 5d098571a3ad434ab5676d529656ac4d: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/a07445f526134d54b4316e8c62220bcf/wal-000000034 (ops 164-168)
I20260812 06:18:56.787417  6519 log.cc:1079] T a07445f526134d54b4316e8c62220bcf P 5d098571a3ad434ab5676d529656ac4d: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/a07445f526134d54b4316e8c62220bcf/wal-000000035 (ops 169-173)
I20260812 06:18:56.787456  6519 log.cc:1079] T a07445f526134d54b4316e8c62220bcf P 5d098571a3ad434ab5676d529656ac4d: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/a07445f526134d54b4316e8c62220bcf/wal-000000036 (ops 174-178)
I20260812 06:18:56.787495  6519 log.cc:1079] T a07445f526134d54b4316e8c62220bcf P 5d098571a3ad434ab5676d529656ac4d: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/a07445f526134d54b4316e8c62220bcf/wal-000000037 (ops 179-183)
I20260812 06:18:56.787539  6519 log.cc:1079] T a07445f526134d54b4316e8c62220bcf P 5d098571a3ad434ab5676d529656ac4d: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/a07445f526134d54b4316e8c62220bcf/wal-000000038 (ops 184-188)
I20260812 06:18:56.830585  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: LogGCOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.044s	user 0.000s	sys 0.043s Metrics: {}
I20260812 06:18:56.831301  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf): perf score=2.188937
I20260812 06:18:56.857568  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.026s	user 0.019s	sys 0.000s Metrics: {"bytes_written":4348807,"delete_count":0,"lbm_write_time_us":7665,"lbm_writes_lt_1ms":109,"reinsert_count":0,"update_count":530}
I20260812 06:18:56.858608  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling UndoDeltaBlockGCOp(a07445f526134d54b4316e8c62220bcf): 528 bytes on disk
I20260812 06:18:56.859602  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: UndoDeltaBlockGCOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":128,"lbm_reads_lt_1ms":4}
I20260812 06:18:56.860349  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf): perf score=2.188937
I20260812 06:18:56.877750  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.017s	user 0.016s	sys 0.000s Metrics: {"bytes_written":3856508,"delete_count":0,"lbm_write_time_us":5816,"lbm_writes_lt_1ms":97,"reinsert_count":0,"update_count":470}
I20260812 06:18:56.878559  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling MajorDeltaCompactionOp(a07445f526134d54b4316e8c62220bcf): perf score=1.000000
I20260812 06:18:57.107537  6406 heavy-update-compaction-itest.cc:229] Time spent updating: real 6.074s	user 2.191s	sys 0.196s
I20260812 06:18:57.216368  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: MajorDeltaCompactionOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.338s	user 0.228s	sys 0.107s Metrics: {"cfile_cache_miss":1035,"cfile_cache_miss_bytes":45205170,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"lbm_read_time_us":25277,"lbm_reads_lt_1ms":1071,"lbm_write_time_us":65060,"lbm_writes_lt_1ms":1043,"peak_mem_usage":125248760,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":5000}
I20260812 06:18:57.217080  6586 maintenance_manager.cc:419] P 5d098571a3ad434ab5676d529656ac4d: Scheduling FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf): perf score=14.095187
I20260812 06:18:57.246191  6406 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.138s	user 0.005s	sys 0.000s
I20260812 06:18:57.247078  6406 tablet_server.cc:179] TabletServer@127.6.65.129:0 shutting down...
I20260812 06:18:57.274458  6519 maintenance_manager.cc:643] P 5d098571a3ad434ab5676d529656ac4d: FlushDeltaMemStoresOp(a07445f526134d54b4316e8c62220bcf) complete. Timing: real 0.057s	user 0.051s	sys 0.004s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25626,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:57.275350  6406 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:57.276265  6406 tablet_replica.cc:333] T a07445f526134d54b4316e8c62220bcf P 5d098571a3ad434ab5676d529656ac4d: stopping tablet replica
I20260812 06:18:57.276578  6406 raft_consensus.cc:2243] T a07445f526134d54b4316e8c62220bcf P 5d098571a3ad434ab5676d529656ac4d [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:57.276950  6406 raft_consensus.cc:2272] T a07445f526134d54b4316e8c62220bcf P 5d098571a3ad434ab5676d529656ac4d [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:57.296391  6406 tablet_server.cc:196] TabletServer@127.6.65.129:0 shutdown complete.
I20260812 06:18:57.338474  6406 master.cc:562] Master@127.6.65.190:45307 shutting down...
I20260812 06:18:57.343770  6406 raft_consensus.cc:2243] T 00000000000000000000000000000000 P d972c1d6536644749f69b33d4a3cb111 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:57.344240  6406 raft_consensus.cc:2272] T 00000000000000000000000000000000 P d972c1d6536644749f69b33d4a3cb111 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:57.344367  6406 tablet_replica.cc:333] T 00000000000000000000000000000000 P d972c1d6536644749f69b33d4a3cb111: stopping tablet replica
I20260812 06:18:57.357877  6406 master.cc:584] Master@127.6.65.190:45307 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (6824 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:57.498083  6406 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.6.65.190:36897
I20260812 06:18:57.498620  6406 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:57.502187  6626 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:57.502175  6627 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:57.502219  6406 server_base.cc:1061] running on GCE node
W20260812 06:18:57.502175  6630 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:57.502810  6406 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:57.502895  6406 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:57.502923  6406 hybrid_clock.cc:648] HybridClock initialized: now 1786515537502922 us; error 0 us; skew 500 ppm
I20260812 06:18:57.504208  6406 webserver.cc:533] Webserver started at http://127.6.65.190:40565/ using document root <none> and password file <none>
I20260812 06:18:57.504456  6406 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:57.504549  6406 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:57.504645  6406 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:57.505239  6406 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515530638234-6406-0/minicluster-data/master-0-root/instance:
uuid: "101a00e9145b4c059d4f0f9d1ced6cc6"
format_stamp: "Formatted at 2026-08-12 06:18:57 on dist-test-slave-77v9"
I20260812 06:18:57.507326  6406 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:18:57.509243  6635 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:57.509729  6406 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.001s	sys 0.001s
I20260812 06:18:57.509878  6406 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515530638234-6406-0/minicluster-data/master-0-root
uuid: "101a00e9145b4c059d4f0f9d1ced6cc6"
format_stamp: "Formatted at 2026-08-12 06:18:57 on dist-test-slave-77v9"
I20260812 06:18:57.509965  6406 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515530638234-6406-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515530638234-6406-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515530638234-6406-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:57.522691  6406 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:57.523195  6406 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:57.528090  6406 rpc_server.cc:307] RPC server started. Bound to: 127.6.65.190:36897
I20260812 06:18:57.528272  6694 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.6.65.190:36897 every 8 connection(s)
I20260812 06:18:57.529493  6695 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:57.531723  6695 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 101a00e9145b4c059d4f0f9d1ced6cc6: Bootstrap starting.
I20260812 06:18:57.532786  6695 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 101a00e9145b4c059d4f0f9d1ced6cc6: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:57.536633  6695 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 101a00e9145b4c059d4f0f9d1ced6cc6: No bootstrap required, opened a new log
I20260812 06:18:57.537454  6695 raft_consensus.cc:359] T 00000000000000000000000000000000 P 101a00e9145b4c059d4f0f9d1ced6cc6 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "101a00e9145b4c059d4f0f9d1ced6cc6" member_type: VOTER }
I20260812 06:18:57.537617  6695 raft_consensus.cc:385] T 00000000000000000000000000000000 P 101a00e9145b4c059d4f0f9d1ced6cc6 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:57.537647  6695 raft_consensus.cc:740] T 00000000000000000000000000000000 P 101a00e9145b4c059d4f0f9d1ced6cc6 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 101a00e9145b4c059d4f0f9d1ced6cc6, State: Initialized, Role: FOLLOWER
I20260812 06:18:57.537847  6695 consensus_queue.cc:260] T 00000000000000000000000000000000 P 101a00e9145b4c059d4f0f9d1ced6cc6 [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: "101a00e9145b4c059d4f0f9d1ced6cc6" member_type: VOTER }
I20260812 06:18:57.537976  6695 raft_consensus.cc:399] T 00000000000000000000000000000000 P 101a00e9145b4c059d4f0f9d1ced6cc6 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:57.538008  6695 raft_consensus.cc:493] T 00000000000000000000000000000000 P 101a00e9145b4c059d4f0f9d1ced6cc6 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:57.538095  6695 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 101a00e9145b4c059d4f0f9d1ced6cc6 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:57.539853  6695 raft_consensus.cc:515] T 00000000000000000000000000000000 P 101a00e9145b4c059d4f0f9d1ced6cc6 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "101a00e9145b4c059d4f0f9d1ced6cc6" member_type: VOTER }
I20260812 06:18:57.540161  6695 leader_election.cc:304] T 00000000000000000000000000000000 P 101a00e9145b4c059d4f0f9d1ced6cc6 [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: 101a00e9145b4c059d4f0f9d1ced6cc6; no voters: 
I20260812 06:18:57.540621  6695 leader_election.cc:290] T 00000000000000000000000000000000 P 101a00e9145b4c059d4f0f9d1ced6cc6 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:57.541004  6698 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 101a00e9145b4c059d4f0f9d1ced6cc6 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:57.541275  6698 raft_consensus.cc:697] T 00000000000000000000000000000000 P 101a00e9145b4c059d4f0f9d1ced6cc6 [term 1 LEADER]: Becoming Leader. State: Replica: 101a00e9145b4c059d4f0f9d1ced6cc6, State: Running, Role: LEADER
I20260812 06:18:57.541415  6695 sys_catalog.cc:565] T 00000000000000000000000000000000 P 101a00e9145b4c059d4f0f9d1ced6cc6 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:57.541524  6698 consensus_queue.cc:237] T 00000000000000000000000000000000 P 101a00e9145b4c059d4f0f9d1ced6cc6 [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: "101a00e9145b4c059d4f0f9d1ced6cc6" member_type: VOTER }
I20260812 06:18:57.542873  6699 sys_catalog.cc:455] T 00000000000000000000000000000000 P 101a00e9145b4c059d4f0f9d1ced6cc6 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "101a00e9145b4c059d4f0f9d1ced6cc6" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "101a00e9145b4c059d4f0f9d1ced6cc6" member_type: VOTER } }
I20260812 06:18:57.543043  6699 sys_catalog.cc:458] T 00000000000000000000000000000000 P 101a00e9145b4c059d4f0f9d1ced6cc6 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:57.543332  6700 sys_catalog.cc:455] T 00000000000000000000000000000000 P 101a00e9145b4c059d4f0f9d1ced6cc6 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 101a00e9145b4c059d4f0f9d1ced6cc6. Latest consensus state: current_term: 1 leader_uuid: "101a00e9145b4c059d4f0f9d1ced6cc6" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "101a00e9145b4c059d4f0f9d1ced6cc6" member_type: VOTER } }
I20260812 06:18:57.543481  6700 sys_catalog.cc:458] T 00000000000000000000000000000000 P 101a00e9145b4c059d4f0f9d1ced6cc6 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:57.543648  6707 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:57.544735  6707 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:57.545076  6406 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:57.548172  6707 catalog_manager.cc:1383] Generated new cluster ID: 6ede256268e04a17bdf888914fccdddf
I20260812 06:18:57.548295  6707 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:57.563367  6707 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:57.564185  6707 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:57.574357  6707 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 101a00e9145b4c059d4f0f9d1ced6cc6: Generated new TSK 0
I20260812 06:18:57.574672  6707 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:57.579280  6406 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:18:57.582161  6406 server_base.cc:1061] running on GCE node
W20260812 06:18:57.582146  6719 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:57.582315  6720 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:57.582139  6722 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:57.582640  6406 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:57.582723  6406 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:57.582747  6406 hybrid_clock.cc:648] HybridClock initialized: now 1786515537582747 us; error 0 us; skew 500 ppm
I20260812 06:18:57.584101  6406 webserver.cc:533] Webserver started at http://127.6.65.129:34225/ using document root <none> and password file <none>
I20260812 06:18:57.584311  6406 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:57.584365  6406 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:57.584487  6406 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:57.585079  6406 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515530638234-6406-0/minicluster-data/ts-0-root/instance:
uuid: "092432dd43d94cdf9339982fe9047346"
format_stamp: "Formatted at 2026-08-12 06:18:57 on dist-test-slave-77v9"
I20260812 06:18:57.587055  6406 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:57.588671  6727 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:57.589200  6406 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:57.589289  6406 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515530638234-6406-0/minicluster-data/ts-0-root
uuid: "092432dd43d94cdf9339982fe9047346"
format_stamp: "Formatted at 2026-08-12 06:18:57 on dist-test-slave-77v9"
I20260812 06:18:57.589460  6406 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515530638234-6406-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515530638234-6406-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515530638234-6406-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:57.608211  6406 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:57.608883  6406 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:57.609316  6406 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:57.609997  6406 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:57.610073  6406 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:57.610144  6406 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:57.610194  6406 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:57.616418  6406 rpc_server.cc:307] RPC server started. Bound to: 127.6.65.129:36405
I20260812 06:18:57.616475  6798 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.6.65.129:36405 every 8 connection(s)
I20260812 06:18:57.629532  6800 heartbeater.cc:344] Connected to a master server at 127.6.65.190:36897
I20260812 06:18:57.629798  6800 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:57.630487  6800 heartbeater.cc:507] Master 127.6.65.190:36897 requested a full tablet report, sending...
I20260812 06:18:57.631886  6654 ts_manager.cc:194] Registered new tserver with Master: 092432dd43d94cdf9339982fe9047346 (127.6.65.129:36405)
I20260812 06:18:57.632459  6406 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.015492836s
I20260812 06:18:57.633178  6654 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:35326
I20260812 06:18:57.646940  6654 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:35328:
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:57.661154  6756 tablet_service.cc:1511] Processing CreateTablet for tablet 237ddc604c694940b9b96c30e4b55eb1 (DEFAULT_TABLE table=heavy-update-compaction-test [id=400ee1063654401f822efed8474c6f5c]), partition=
I20260812 06:18:57.661549  6756 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 237ddc604c694940b9b96c30e4b55eb1. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:57.664091  6813 tablet_bootstrap.cc:492] T 237ddc604c694940b9b96c30e4b55eb1 P 092432dd43d94cdf9339982fe9047346: Bootstrap starting.
I20260812 06:18:57.665375  6813 tablet_bootstrap.cc:654] T 237ddc604c694940b9b96c30e4b55eb1 P 092432dd43d94cdf9339982fe9047346: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:57.666934  6813 tablet_bootstrap.cc:492] T 237ddc604c694940b9b96c30e4b55eb1 P 092432dd43d94cdf9339982fe9047346: No bootstrap required, opened a new log
I20260812 06:18:57.667083  6813 ts_tablet_manager.cc:1403] T 237ddc604c694940b9b96c30e4b55eb1 P 092432dd43d94cdf9339982fe9047346: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:18:57.667704  6813 raft_consensus.cc:359] T 237ddc604c694940b9b96c30e4b55eb1 P 092432dd43d94cdf9339982fe9047346 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "092432dd43d94cdf9339982fe9047346" member_type: VOTER last_known_addr { host: "127.6.65.129" port: 36405 } }
I20260812 06:18:57.667870  6813 raft_consensus.cc:385] T 237ddc604c694940b9b96c30e4b55eb1 P 092432dd43d94cdf9339982fe9047346 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:57.667912  6813 raft_consensus.cc:740] T 237ddc604c694940b9b96c30e4b55eb1 P 092432dd43d94cdf9339982fe9047346 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 092432dd43d94cdf9339982fe9047346, State: Initialized, Role: FOLLOWER
I20260812 06:18:57.668174  6813 consensus_queue.cc:260] T 237ddc604c694940b9b96c30e4b55eb1 P 092432dd43d94cdf9339982fe9047346 [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: "092432dd43d94cdf9339982fe9047346" member_type: VOTER last_known_addr { host: "127.6.65.129" port: 36405 } }
I20260812 06:18:57.668275  6813 raft_consensus.cc:399] T 237ddc604c694940b9b96c30e4b55eb1 P 092432dd43d94cdf9339982fe9047346 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:57.668304  6813 raft_consensus.cc:493] T 237ddc604c694940b9b96c30e4b55eb1 P 092432dd43d94cdf9339982fe9047346 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:57.668344  6813 raft_consensus.cc:3060] T 237ddc604c694940b9b96c30e4b55eb1 P 092432dd43d94cdf9339982fe9047346 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:57.669363  6813 raft_consensus.cc:515] T 237ddc604c694940b9b96c30e4b55eb1 P 092432dd43d94cdf9339982fe9047346 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "092432dd43d94cdf9339982fe9047346" member_type: VOTER last_known_addr { host: "127.6.65.129" port: 36405 } }
I20260812 06:18:57.669515  6813 leader_election.cc:304] T 237ddc604c694940b9b96c30e4b55eb1 P 092432dd43d94cdf9339982fe9047346 [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: 092432dd43d94cdf9339982fe9047346; no voters: 
I20260812 06:18:57.669732  6813 leader_election.cc:290] T 237ddc604c694940b9b96c30e4b55eb1 P 092432dd43d94cdf9339982fe9047346 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:57.669939  6815 raft_consensus.cc:2804] T 237ddc604c694940b9b96c30e4b55eb1 P 092432dd43d94cdf9339982fe9047346 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:57.670148  6800 heartbeater.cc:499] Master 127.6.65.190:36897 was elected leader, sending a full tablet report...
I20260812 06:18:57.670173  6815 raft_consensus.cc:697] T 237ddc604c694940b9b96c30e4b55eb1 P 092432dd43d94cdf9339982fe9047346 [term 1 LEADER]: Becoming Leader. State: Replica: 092432dd43d94cdf9339982fe9047346, State: Running, Role: LEADER
I20260812 06:18:57.670152  6813 ts_tablet_manager.cc:1434] T 237ddc604c694940b9b96c30e4b55eb1 P 092432dd43d94cdf9339982fe9047346: Time spent starting tablet: real 0.003s	user 0.004s	sys 0.000s
I20260812 06:18:57.670388  6815 consensus_queue.cc:237] T 237ddc604c694940b9b96c30e4b55eb1 P 092432dd43d94cdf9339982fe9047346 [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: "092432dd43d94cdf9339982fe9047346" member_type: VOTER last_known_addr { host: "127.6.65.129" port: 36405 } }
I20260812 06:18:57.672338  6653 catalog_manager.cc:5719] T 237ddc604c694940b9b96c30e4b55eb1 P 092432dd43d94cdf9339982fe9047346 reported cstate change: term changed from 0 to 1, leader changed from <none> to 092432dd43d94cdf9339982fe9047346 (127.6.65.129). New cstate: current_term: 1 leader_uuid: "092432dd43d94cdf9339982fe9047346" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "092432dd43d94cdf9339982fe9047346" member_type: VOTER last_known_addr { host: "127.6.65.129" port: 36405 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:57.742547  6406 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.063s	user 0.016s	sys 0.010s
I20260812 06:18:57.867630  6801 maintenance_manager.cc:419] P 092432dd43d94cdf9339982fe9047346: Scheduling FlushMRSOp(237ddc604c694940b9b96c30e4b55eb1): perf score=15.086190
I20260812 06:18:58.022879  6733 maintenance_manager.cc:643] P 092432dd43d94cdf9339982fe9047346: FlushMRSOp(237ddc604c694940b9b96c30e4b55eb1) complete. Timing: real 0.155s	user 0.121s	sys 0.032s Metrics: {"bytes_written":8615321,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":138,"dirs.run_cpu_time_us":317,"dirs.run_wall_time_us":1287,"drs_written":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4,"lbm_write_time_us":39061,"lbm_writes_lt_1ms":567,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"update_count":1050}
I20260812 06:18:58.023913  6801 maintenance_manager.cc:419] P 092432dd43d94cdf9339982fe9047346: Scheduling LogGCOp(237ddc604c694940b9b96c30e4b55eb1): free 11976772 bytes of WAL
I20260812 06:18:58.024528  6733 log_reader.cc:385] T 237ddc604c694940b9b96c30e4b55eb1: removed 1 log segments from log reader
I20260812 06:18:58.024894  6733 log.cc:1079] T 237ddc604c694940b9b96c30e4b55eb1 P 092432dd43d94cdf9339982fe9047346: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/237ddc604c694940b9b96c30e4b55eb1/wal-000000001 (ops 1-6)
I20260812 06:18:58.027712  6733 maintenance_manager.cc:643] P 092432dd43d94cdf9339982fe9047346: LogGCOp(237ddc604c694940b9b96c30e4b55eb1) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:18:58.028260  6801 maintenance_manager.cc:419] P 092432dd43d94cdf9339982fe9047346: Scheduling UndoDeltaBlockGCOp(237ddc604c694940b9b96c30e4b55eb1): 12308957 bytes on disk
I20260812 06:18:58.028792  6733 maintenance_manager.cc:643] P 092432dd43d94cdf9339982fe9047346: UndoDeltaBlockGCOp(237ddc604c694940b9b96c30e4b55eb1) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":69,"lbm_reads_lt_1ms":4}
I20260812 06:18:58.029376  6801 maintenance_manager.cc:419] P 092432dd43d94cdf9339982fe9047346: Scheduling FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1): perf score=2.188937
I20260812 06:18:58.050344  6733 maintenance_manager.cc:643] P 092432dd43d94cdf9339982fe9047346: FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1) complete. Timing: real 0.021s	user 0.003s	sys 0.011s Metrics: {"bytes_written":3692409,"delete_count":0,"lbm_write_time_us":6077,"lbm_writes_lt_1ms":93,"reinsert_count":0,"spinlock_wait_cycles":80640,"update_count":450}
I20260812 06:18:58.051054  6801 maintenance_manager.cc:419] P 092432dd43d94cdf9339982fe9047346: Scheduling MajorDeltaCompactionOp(237ddc604c694940b9b96c30e4b55eb1): perf score=1.000000
I20260812 06:18:58.186715  6733 maintenance_manager.cc:643] P 092432dd43d94cdf9339982fe9047346: MajorDeltaCompactionOp(237ddc604c694940b9b96c30e4b55eb1) complete. Timing: real 0.135s	user 0.103s	sys 0.031s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16528893,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":835,"lbm_read_time_us":9516,"lbm_reads_lt_1ms":360,"lbm_write_time_us":21125,"lbm_writes_lt_1ms":343,"peak_mem_usage":38262756,"reinsert_count":0,"thread_start_us":408,"threads_started":5,"update_count":1500}
I20260812 06:18:58.187564  6801 maintenance_manager.cc:419] P 092432dd43d94cdf9339982fe9047346: Scheduling FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1): perf score=10.126437
I20260812 06:18:58.245162  6733 maintenance_manager.cc:643] P 092432dd43d94cdf9339982fe9047346: FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1) complete. Timing: real 0.057s	user 0.032s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":21131,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:58.245868  6801 maintenance_manager.cc:419] P 092432dd43d94cdf9339982fe9047346: Scheduling FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1): perf score=2.188937
I20260812 06:18:58.259799  6733 maintenance_manager.cc:643] P 092432dd43d94cdf9339982fe9047346: FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1) complete. Timing: real 0.014s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4846,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:58.260716  6801 maintenance_manager.cc:419] P 092432dd43d94cdf9339982fe9047346: Scheduling MajorDeltaCompactionOp(237ddc604c694940b9b96c30e4b55eb1): perf score=1.000000
I20260812 06:18:58.402904  6733 maintenance_manager.cc:643] P 092432dd43d94cdf9339982fe9047346: MajorDeltaCompactionOp(237ddc604c694940b9b96c30e4b55eb1) complete. Timing: real 0.142s	user 0.105s	sys 0.037s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":384,"lbm_read_time_us":10671,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25413,"lbm_writes_lt_1ms":443,"mutex_wait_us":81,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":20352,"update_count":2000}
I20260812 06:18:58.403898  6801 maintenance_manager.cc:419] P 092432dd43d94cdf9339982fe9047346: Scheduling FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1): perf score=10.126437
I20260812 06:18:58.468470  6733 maintenance_manager.cc:643] P 092432dd43d94cdf9339982fe9047346: FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1) complete. Timing: real 0.064s	user 0.033s	sys 0.026s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19400,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:58.469738  6801 maintenance_manager.cc:419] P 092432dd43d94cdf9339982fe9047346: Scheduling FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1): perf score=2.188937
I20260812 06:18:58.492354  6733 maintenance_manager.cc:643] P 092432dd43d94cdf9339982fe9047346: FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1) complete. Timing: real 0.022s	user 0.015s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7646,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:58.493237  6801 maintenance_manager.cc:419] P 092432dd43d94cdf9339982fe9047346: Scheduling MajorDeltaCompactionOp(237ddc604c694940b9b96c30e4b55eb1): perf score=1.000000
I20260812 06:18:58.695668  6733 maintenance_manager.cc:643] P 092432dd43d94cdf9339982fe9047346: MajorDeltaCompactionOp(237ddc604c694940b9b96c30e4b55eb1) complete. Timing: real 0.202s	user 0.125s	sys 0.077s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":709,"lbm_read_time_us":14264,"lbm_reads_lt_1ms":472,"lbm_write_time_us":34041,"lbm_writes_lt_1ms":443,"mutex_wait_us":33,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12416,"update_count":2000}
I20260812 06:18:58.696429  6801 maintenance_manager.cc:419] P 092432dd43d94cdf9339982fe9047346: Scheduling FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1): perf score=10.126437
I20260812 06:18:58.750577  6733 maintenance_manager.cc:643] P 092432dd43d94cdf9339982fe9047346: FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1) complete. Timing: real 0.054s	user 0.034s	sys 0.012s Metrics: {"bytes_written":12307494,"delete_count":0,"lbm_write_time_us":21056,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:58.751297  6801 maintenance_manager.cc:419] P 092432dd43d94cdf9339982fe9047346: Scheduling FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1): perf score=2.188937
I20260812 06:18:58.764701  6733 maintenance_manager.cc:643] P 092432dd43d94cdf9339982fe9047346: FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4785,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:58.765337  6801 maintenance_manager.cc:419] P 092432dd43d94cdf9339982fe9047346: Scheduling MajorDeltaCompactionOp(237ddc604c694940b9b96c30e4b55eb1): perf score=1.000000
I20260812 06:18:58.919860  6733 maintenance_manager.cc:643] P 092432dd43d94cdf9339982fe9047346: MajorDeltaCompactionOp(237ddc604c694940b9b96c30e4b55eb1) complete. Timing: real 0.154s	user 0.117s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631316,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1402,"lbm_read_time_us":9936,"lbm_reads_lt_1ms":472,"lbm_write_time_us":30047,"lbm_writes_lt_1ms":443,"mutex_wait_us":260,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11264,"update_count":2000}
I20260812 06:18:58.921183  6801 maintenance_manager.cc:419] P 092432dd43d94cdf9339982fe9047346: Scheduling FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1): perf score=10.126437
I20260812 06:18:58.977552  6733 maintenance_manager.cc:643] P 092432dd43d94cdf9339982fe9047346: FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1) complete. Timing: real 0.056s	user 0.035s	sys 0.020s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":24666,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:58.978212  6801 maintenance_manager.cc:419] P 092432dd43d94cdf9339982fe9047346: Scheduling FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1): perf score=2.188937
I20260812 06:18:58.992445  6733 maintenance_manager.cc:643] P 092432dd43d94cdf9339982fe9047346: FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5216,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:58.993206  6801 maintenance_manager.cc:419] P 092432dd43d94cdf9339982fe9047346: Scheduling MajorDeltaCompactionOp(237ddc604c694940b9b96c30e4b55eb1): perf score=1.000000
I20260812 06:18:59.143275  6733 maintenance_manager.cc:643] P 092432dd43d94cdf9339982fe9047346: MajorDeltaCompactionOp(237ddc604c694940b9b96c30e4b55eb1) complete. Timing: real 0.150s	user 0.123s	sys 0.025s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1767,"lbm_read_time_us":11698,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28901,"lbm_writes_lt_1ms":443,"mutex_wait_us":476,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2000}
I20260812 06:18:59.144256  6801 maintenance_manager.cc:419] P 092432dd43d94cdf9339982fe9047346: Scheduling FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1): perf score=11.118625
I20260812 06:18:59.204525  6733 maintenance_manager.cc:643] P 092432dd43d94cdf9339982fe9047346: FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1) complete. Timing: real 0.060s	user 0.034s	sys 0.022s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":21933,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":311,"reinsert_count":0,"update_count":1550}
I20260812 06:18:59.205132  6801 maintenance_manager.cc:419] P 092432dd43d94cdf9339982fe9047346: Scheduling FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1): perf score=2.188937
I20260812 06:18:59.225011  6733 maintenance_manager.cc:643] P 092432dd43d94cdf9339982fe9047346: FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1) complete. Timing: real 0.020s	user 0.009s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4644,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:59.225680  6801 maintenance_manager.cc:419] P 092432dd43d94cdf9339982fe9047346: Scheduling FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1): perf score=2.188937
I20260812 06:18:59.238801  6733 maintenance_manager.cc:643] P 092432dd43d94cdf9339982fe9047346: FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1) complete. Timing: real 0.013s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4761,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:59.239548  6801 maintenance_manager.cc:419] P 092432dd43d94cdf9339982fe9047346: Scheduling MajorDeltaCompactionOp(237ddc604c694940b9b96c30e4b55eb1): perf score=1.000000
I20260812 06:18:59.460211  6733 maintenance_manager.cc:643] P 092432dd43d94cdf9339982fe9047346: MajorDeltaCompactionOp(237ddc604c694940b9b96c30e4b55eb1) complete. Timing: real 0.220s	user 0.125s	sys 0.092s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733834,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1846,"lbm_read_time_us":15142,"lbm_reads_lt_1ms":573,"lbm_write_time_us":34196,"lbm_writes_lt_1ms":543,"mutex_wait_us":641,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7040,"update_count":2500}
I20260812 06:18:59.461153  6801 maintenance_manager.cc:419] P 092432dd43d94cdf9339982fe9047346: Scheduling FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1): perf score=14.095187
I20260812 06:18:59.536755  6733 maintenance_manager.cc:643] P 092432dd43d94cdf9339982fe9047346: FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1) complete. Timing: real 0.075s	user 0.044s	sys 0.028s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":26891,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:59.537580  6801 maintenance_manager.cc:419] P 092432dd43d94cdf9339982fe9047346: Scheduling FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1): perf score=2.188937
I20260812 06:18:59.551067  6733 maintenance_manager.cc:643] P 092432dd43d94cdf9339982fe9047346: FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1) complete. Timing: real 0.013s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5297,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:59.552060  6801 maintenance_manager.cc:419] P 092432dd43d94cdf9339982fe9047346: Scheduling FlushMRSOp(237ddc604c694940b9b96c30e4b55eb1): perf score=1.000000
I20260812 06:18:59.604645  6733 maintenance_manager.cc:643] P 092432dd43d94cdf9339982fe9047346: FlushMRSOp(237ddc604c694940b9b96c30e4b55eb1) complete. Timing: real 0.052s	user 0.032s	sys 0.004s Metrics: {"bytes_written":1193504,"cfile_init":1,"dirs.queue_time_us":99,"dirs.run_cpu_time_us":328,"dirs.run_wall_time_us":1694,"drs_written":1,"lbm_read_time_us":46,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1978,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:59.605495  6801 maintenance_manager.cc:419] P 092432dd43d94cdf9339982fe9047346: Scheduling LogGCOp(237ddc604c694940b9b96c30e4b55eb1): free 125163538 bytes of WAL
I20260812 06:18:59.605784  6733 log_reader.cc:385] T 237ddc604c694940b9b96c30e4b55eb1: removed 13 log segments from log reader
I20260812 06:18:59.605856  6733 log.cc:1079] T 237ddc604c694940b9b96c30e4b55eb1 P 092432dd43d94cdf9339982fe9047346: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/237ddc604c694940b9b96c30e4b55eb1/wal-000000002 (ops 7-11)
I20260812 06:18:59.605916  6733 log.cc:1079] T 237ddc604c694940b9b96c30e4b55eb1 P 092432dd43d94cdf9339982fe9047346: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/237ddc604c694940b9b96c30e4b55eb1/wal-000000003 (ops 12-16)
I20260812 06:18:59.605986  6733 log.cc:1079] T 237ddc604c694940b9b96c30e4b55eb1 P 092432dd43d94cdf9339982fe9047346: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/237ddc604c694940b9b96c30e4b55eb1/wal-000000004 (ops 17-20)
I20260812 06:18:59.606036  6733 log.cc:1079] T 237ddc604c694940b9b96c30e4b55eb1 P 092432dd43d94cdf9339982fe9047346: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/237ddc604c694940b9b96c30e4b55eb1/wal-000000005 (ops 21-25)
I20260812 06:18:59.606079  6733 log.cc:1079] T 237ddc604c694940b9b96c30e4b55eb1 P 092432dd43d94cdf9339982fe9047346: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/237ddc604c694940b9b96c30e4b55eb1/wal-000000006 (ops 26-30)
I20260812 06:18:59.606125  6733 log.cc:1079] T 237ddc604c694940b9b96c30e4b55eb1 P 092432dd43d94cdf9339982fe9047346: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/237ddc604c694940b9b96c30e4b55eb1/wal-000000007 (ops 31-34)
I20260812 06:18:59.606170  6733 log.cc:1079] T 237ddc604c694940b9b96c30e4b55eb1 P 092432dd43d94cdf9339982fe9047346: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/237ddc604c694940b9b96c30e4b55eb1/wal-000000008 (ops 35-39)
I20260812 06:18:59.606215  6733 log.cc:1079] T 237ddc604c694940b9b96c30e4b55eb1 P 092432dd43d94cdf9339982fe9047346: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/237ddc604c694940b9b96c30e4b55eb1/wal-000000009 (ops 40-44)
I20260812 06:18:59.606257  6733 log.cc:1079] T 237ddc604c694940b9b96c30e4b55eb1 P 092432dd43d94cdf9339982fe9047346: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/237ddc604c694940b9b96c30e4b55eb1/wal-000000010 (ops 45-48)
I20260812 06:18:59.606302  6733 log.cc:1079] T 237ddc604c694940b9b96c30e4b55eb1 P 092432dd43d94cdf9339982fe9047346: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/237ddc604c694940b9b96c30e4b55eb1/wal-000000011 (ops 49-53)
I20260812 06:18:59.606346  6733 log.cc:1079] T 237ddc604c694940b9b96c30e4b55eb1 P 092432dd43d94cdf9339982fe9047346: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/237ddc604c694940b9b96c30e4b55eb1/wal-000000012 (ops 54-58)
I20260812 06:18:59.606392  6733 log.cc:1079] T 237ddc604c694940b9b96c30e4b55eb1 P 092432dd43d94cdf9339982fe9047346: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/237ddc604c694940b9b96c30e4b55eb1/wal-000000013 (ops 59-62)
I20260812 06:18:59.606436  6733 log.cc:1079] T 237ddc604c694940b9b96c30e4b55eb1 P 092432dd43d94cdf9339982fe9047346: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/237ddc604c694940b9b96c30e4b55eb1/wal-000000014 (ops 63-67)
I20260812 06:18:59.639355  6733 maintenance_manager.cc:643] P 092432dd43d94cdf9339982fe9047346: LogGCOp(237ddc604c694940b9b96c30e4b55eb1) complete. Timing: real 0.034s	user 0.000s	sys 0.031s Metrics: {}
I20260812 06:18:59.639911  6801 maintenance_manager.cc:419] P 092432dd43d94cdf9339982fe9047346: Scheduling UndoDeltaBlockGCOp(237ddc604c694940b9b96c30e4b55eb1): 462 bytes on disk
I20260812 06:18:59.640408  6733 maintenance_manager.cc:643] P 092432dd43d94cdf9339982fe9047346: UndoDeltaBlockGCOp(237ddc604c694940b9b96c30e4b55eb1) 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:59.641060  6801 maintenance_manager.cc:419] P 092432dd43d94cdf9339982fe9047346: Scheduling FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1): perf score=3.181125
I20260812 06:18:59.657037  6733 maintenance_manager.cc:643] P 092432dd43d94cdf9339982fe9047346: FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1) complete. Timing: real 0.016s	user 0.007s	sys 0.009s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":6379,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:59.657688  6801 maintenance_manager.cc:419] P 092432dd43d94cdf9339982fe9047346: Scheduling FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1): perf score=2.188937
I20260812 06:18:59.669706  6733 maintenance_manager.cc:643] P 092432dd43d94cdf9339982fe9047346: FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4499,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:59.670272  6801 maintenance_manager.cc:419] P 092432dd43d94cdf9339982fe9047346: Scheduling MajorDeltaCompactionOp(237ddc604c694940b9b96c30e4b55eb1): perf score=1.000000
I20260812 06:18:59.962275  6733 maintenance_manager.cc:643] P 092432dd43d94cdf9339982fe9047346: MajorDeltaCompactionOp(237ddc604c694940b9b96c30e4b55eb1) complete. Timing: real 0.292s	user 0.192s	sys 0.100s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32938772,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1215,"lbm_read_time_us":25367,"lbm_reads_lt_1ms":774,"lbm_write_time_us":47489,"lbm_writes_lt_1ms":743,"mutex_wait_us":130,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":15488,"thread_start_us":101,"threads_started":1,"update_count":3500}
I20260812 06:18:59.963150  6801 maintenance_manager.cc:419] P 092432dd43d94cdf9339982fe9047346: Scheduling FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1): perf score=18.063937
I20260812 06:19:00.041213  6733 maintenance_manager.cc:643] P 092432dd43d94cdf9339982fe9047346: FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1) complete. Timing: real 0.078s	user 0.062s	sys 0.016s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":34724,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:00.041851  6801 maintenance_manager.cc:419] P 092432dd43d94cdf9339982fe9047346: Scheduling FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1): perf score=2.188937
I20260812 06:19:00.061987  6733 maintenance_manager.cc:643] P 092432dd43d94cdf9339982fe9047346: FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1) complete. Timing: real 0.020s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6238,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:00.062564  6801 maintenance_manager.cc:419] P 092432dd43d94cdf9339982fe9047346: Scheduling MajorDeltaCompactionOp(237ddc604c694940b9b96c30e4b55eb1): perf score=1.000000
I20260812 06:19:00.278004  6733 maintenance_manager.cc:643] P 092432dd43d94cdf9339982fe9047346: MajorDeltaCompactionOp(237ddc604c694940b9b96c30e4b55eb1) complete. Timing: real 0.215s	user 0.164s	sys 0.048s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28836137,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1189,"lbm_read_time_us":14650,"lbm_reads_lt_1ms":664,"lbm_write_time_us":44766,"lbm_writes_lt_1ms":643,"mutex_wait_us":347,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":3000}
I20260812 06:19:00.278733  6801 maintenance_manager.cc:419] P 092432dd43d94cdf9339982fe9047346: Scheduling FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1): perf score=15.087375
I20260812 06:19:00.346781  6733 maintenance_manager.cc:643] P 092432dd43d94cdf9339982fe9047346: FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1) complete. Timing: real 0.068s	user 0.045s	sys 0.020s Metrics: {"bytes_written":16820141,"delete_count":0,"lbm_write_time_us":29477,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":412,"reinsert_count":0,"update_count":2050}
I20260812 06:19:00.347381  6801 maintenance_manager.cc:419] P 092432dd43d94cdf9339982fe9047346: Scheduling FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1): perf score=2.188937
I20260812 06:19:00.370155  6733 maintenance_manager.cc:643] P 092432dd43d94cdf9339982fe9047346: FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1) complete. Timing: real 0.023s	user 0.009s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5193,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:00.370862  6801 maintenance_manager.cc:419] P 092432dd43d94cdf9339982fe9047346: Scheduling FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1): perf score=2.188937
I20260812 06:19:00.387167  6733 maintenance_manager.cc:643] P 092432dd43d94cdf9339982fe9047346: FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1) complete. Timing: real 0.016s	user 0.011s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6032,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:00.387789  6801 maintenance_manager.cc:419] P 092432dd43d94cdf9339982fe9047346: Scheduling MajorDeltaCompactionOp(237ddc604c694940b9b96c30e4b55eb1): perf score=1.000000
I20260812 06:19:00.596697  6733 maintenance_manager.cc:643] P 092432dd43d94cdf9339982fe9047346: MajorDeltaCompactionOp(237ddc604c694940b9b96c30e4b55eb1) complete. Timing: real 0.209s	user 0.151s	sys 0.051s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28836240,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":238,"lbm_read_time_us":15508,"lbm_reads_lt_1ms":673,"lbm_write_time_us":43930,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3968,"update_count":3000}
I20260812 06:19:00.597479  6801 maintenance_manager.cc:419] P 092432dd43d94cdf9339982fe9047346: Scheduling FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1): perf score=14.095187
I20260812 06:19:00.673174  6733 maintenance_manager.cc:643] P 092432dd43d94cdf9339982fe9047346: FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1) complete. Timing: real 0.076s	user 0.047s	sys 0.021s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":30736,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:00.673986  6801 maintenance_manager.cc:419] P 092432dd43d94cdf9339982fe9047346: Scheduling FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1): perf score=2.188937
I20260812 06:19:00.689141  6733 maintenance_manager.cc:643] P 092432dd43d94cdf9339982fe9047346: FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1) complete. Timing: real 0.015s	user 0.012s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5139,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:00.689983  6801 maintenance_manager.cc:419] P 092432dd43d94cdf9339982fe9047346: Scheduling MajorDeltaCompactionOp(237ddc604c694940b9b96c30e4b55eb1): perf score=1.000000
I20260812 06:19:00.874172  6733 maintenance_manager.cc:643] P 092432dd43d94cdf9339982fe9047346: MajorDeltaCompactionOp(237ddc604c694940b9b96c30e4b55eb1) complete. Timing: real 0.184s	user 0.131s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":499,"lbm_read_time_us":13427,"lbm_reads_lt_1ms":572,"lbm_write_time_us":36678,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":71424,"update_count":2500}
I20260812 06:19:00.875510  6801 maintenance_manager.cc:419] P 092432dd43d94cdf9339982fe9047346: Scheduling FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1): perf score=14.095187
I20260812 06:19:00.942278  6733 maintenance_manager.cc:643] P 092432dd43d94cdf9339982fe9047346: FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1) complete. Timing: real 0.066s	user 0.046s	sys 0.019s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":30052,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:00.942948  6801 maintenance_manager.cc:419] P 092432dd43d94cdf9339982fe9047346: Scheduling FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1): perf score=2.188937
I20260812 06:19:00.961827  6733 maintenance_manager.cc:643] P 092432dd43d94cdf9339982fe9047346: FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1) complete. Timing: real 0.019s	user 0.014s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6874,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:00.962479  6801 maintenance_manager.cc:419] P 092432dd43d94cdf9339982fe9047346: Scheduling MajorDeltaCompactionOp(237ddc604c694940b9b96c30e4b55eb1): perf score=1.000000
I20260812 06:19:01.162662  6733 maintenance_manager.cc:643] P 092432dd43d94cdf9339982fe9047346: MajorDeltaCompactionOp(237ddc604c694940b9b96c30e4b55eb1) complete. Timing: real 0.200s	user 0.152s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733722,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":313,"lbm_read_time_us":14063,"lbm_reads_lt_1ms":564,"lbm_write_time_us":35712,"lbm_writes_lt_1ms":543,"mutex_wait_us":104,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":57984,"update_count":2500}
I20260812 06:19:01.163411  6801 maintenance_manager.cc:419] P 092432dd43d94cdf9339982fe9047346: Scheduling FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1): perf score=14.095187
I20260812 06:19:01.226918  6733 maintenance_manager.cc:643] P 092432dd43d94cdf9339982fe9047346: FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1) complete. Timing: real 0.063s	user 0.040s	sys 0.019s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":28544,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:01.227594  6801 maintenance_manager.cc:419] P 092432dd43d94cdf9339982fe9047346: Scheduling FlushMRSOp(237ddc604c694940b9b96c30e4b55eb1): perf score=1.000000
I20260812 06:19:01.268558  6733 maintenance_manager.cc:643] P 092432dd43d94cdf9339982fe9047346: FlushMRSOp(237ddc604c694940b9b96c30e4b55eb1) complete. Timing: real 0.041s	user 0.026s	sys 0.003s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":114,"dirs.run_cpu_time_us":383,"dirs.run_wall_time_us":2060,"drs_written":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2634,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:19:01.269704  6801 maintenance_manager.cc:419] P 092432dd43d94cdf9339982fe9047346: Scheduling LogGCOp(237ddc604c694940b9b96c30e4b55eb1): free 108535506 bytes of WAL
I20260812 06:19:01.270143  6733 log_reader.cc:385] T 237ddc604c694940b9b96c30e4b55eb1: removed 11 log segments from log reader
I20260812 06:19:01.270224  6733 log.cc:1079] T 237ddc604c694940b9b96c30e4b55eb1 P 092432dd43d94cdf9339982fe9047346: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/237ddc604c694940b9b96c30e4b55eb1/wal-000000015 (ops 68-72)
I20260812 06:19:01.270287  6733 log.cc:1079] T 237ddc604c694940b9b96c30e4b55eb1 P 092432dd43d94cdf9339982fe9047346: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/237ddc604c694940b9b96c30e4b55eb1/wal-000000016 (ops 73-76)
I20260812 06:19:01.270327  6733 log.cc:1079] T 237ddc604c694940b9b96c30e4b55eb1 P 092432dd43d94cdf9339982fe9047346: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/237ddc604c694940b9b96c30e4b55eb1/wal-000000017 (ops 77-81)
I20260812 06:19:01.270380  6733 log.cc:1079] T 237ddc604c694940b9b96c30e4b55eb1 P 092432dd43d94cdf9339982fe9047346: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/237ddc604c694940b9b96c30e4b55eb1/wal-000000018 (ops 82-86)
I20260812 06:19:01.270417  6733 log.cc:1079] T 237ddc604c694940b9b96c30e4b55eb1 P 092432dd43d94cdf9339982fe9047346: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/237ddc604c694940b9b96c30e4b55eb1/wal-000000019 (ops 87-90)
I20260812 06:19:01.270462  6733 log.cc:1079] T 237ddc604c694940b9b96c30e4b55eb1 P 092432dd43d94cdf9339982fe9047346: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/237ddc604c694940b9b96c30e4b55eb1/wal-000000020 (ops 91-95)
I20260812 06:19:01.270511  6733 log.cc:1079] T 237ddc604c694940b9b96c30e4b55eb1 P 092432dd43d94cdf9339982fe9047346: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/237ddc604c694940b9b96c30e4b55eb1/wal-000000021 (ops 96-100)
I20260812 06:19:01.270551  6733 log.cc:1079] T 237ddc604c694940b9b96c30e4b55eb1 P 092432dd43d94cdf9339982fe9047346: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/237ddc604c694940b9b96c30e4b55eb1/wal-000000022 (ops 101-105)
I20260812 06:19:01.270597  6733 log.cc:1079] T 237ddc604c694940b9b96c30e4b55eb1 P 092432dd43d94cdf9339982fe9047346: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/237ddc604c694940b9b96c30e4b55eb1/wal-000000023 (ops 106-110)
I20260812 06:19:01.270645  6733 log.cc:1079] T 237ddc604c694940b9b96c30e4b55eb1 P 092432dd43d94cdf9339982fe9047346: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/237ddc604c694940b9b96c30e4b55eb1/wal-000000024 (ops 111-115)
I20260812 06:19:01.270695  6733 log.cc:1079] T 237ddc604c694940b9b96c30e4b55eb1 P 092432dd43d94cdf9339982fe9047346: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/237ddc604c694940b9b96c30e4b55eb1/wal-000000025 (ops 116-120)
I20260812 06:19:01.296197  6733 maintenance_manager.cc:643] P 092432dd43d94cdf9339982fe9047346: LogGCOp(237ddc604c694940b9b96c30e4b55eb1) complete. Timing: real 0.026s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:19:01.296778  6801 maintenance_manager.cc:419] P 092432dd43d94cdf9339982fe9047346: Scheduling UndoDeltaBlockGCOp(237ddc604c694940b9b96c30e4b55eb1): 463 bytes on disk
I20260812 06:19:01.297394  6733 maintenance_manager.cc:643] P 092432dd43d94cdf9339982fe9047346: UndoDeltaBlockGCOp(237ddc604c694940b9b96c30e4b55eb1) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":77,"lbm_reads_lt_1ms":4}
I20260812 06:19:01.298029  6801 maintenance_manager.cc:419] P 092432dd43d94cdf9339982fe9047346: Scheduling FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1): perf score=6.157687
I20260812 06:19:01.328002  6733 maintenance_manager.cc:643] P 092432dd43d94cdf9339982fe9047346: FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1) complete. Timing: real 0.030s	user 0.021s	sys 0.004s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":11967,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:19:01.328627  6801 maintenance_manager.cc:419] P 092432dd43d94cdf9339982fe9047346: Scheduling LogGCOp(237ddc604c694940b9b96c30e4b55eb1): free 12017925 bytes of WAL
I20260812 06:19:01.328943  6733 log_reader.cc:385] T 237ddc604c694940b9b96c30e4b55eb1: removed 1 log segments from log reader
I20260812 06:19:01.328992  6733 log.cc:1079] T 237ddc604c694940b9b96c30e4b55eb1 P 092432dd43d94cdf9339982fe9047346: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/237ddc604c694940b9b96c30e4b55eb1/wal-000000026 (ops 121-125)
I20260812 06:19:01.331805  6733 maintenance_manager.cc:643] P 092432dd43d94cdf9339982fe9047346: LogGCOp(237ddc604c694940b9b96c30e4b55eb1) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:19:01.332273  6801 maintenance_manager.cc:419] P 092432dd43d94cdf9339982fe9047346: Scheduling MajorDeltaCompactionOp(237ddc604c694940b9b96c30e4b55eb1): perf score=1.000000
I20260812 06:19:01.587610  6733 maintenance_manager.cc:643] P 092432dd43d94cdf9339982fe9047346: MajorDeltaCompactionOp(237ddc604c694940b9b96c30e4b55eb1) complete. Timing: real 0.255s	user 0.191s	sys 0.052s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28836139,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":732,"lbm_read_time_us":17641,"lbm_reads_lt_1ms":664,"lbm_write_time_us":40477,"lbm_writes_lt_1ms":643,"mutex_wait_us":54,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":30336,"thread_start_us":99,"threads_started":1,"update_count":3000}
I20260812 06:19:01.588470  6801 maintenance_manager.cc:419] P 092432dd43d94cdf9339982fe9047346: Scheduling FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1): perf score=18.063937
I20260812 06:19:01.665432  6733 maintenance_manager.cc:643] P 092432dd43d94cdf9339982fe9047346: FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1) complete. Timing: real 0.077s	user 0.053s	sys 0.023s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":35348,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:01.666121  6801 maintenance_manager.cc:419] P 092432dd43d94cdf9339982fe9047346: Scheduling FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1): perf score=2.188937
I20260812 06:19:01.682273  6733 maintenance_manager.cc:643] P 092432dd43d94cdf9339982fe9047346: FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1) complete. Timing: real 0.016s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5757,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:01.682807  6801 maintenance_manager.cc:419] P 092432dd43d94cdf9339982fe9047346: Scheduling MajorDeltaCompactionOp(237ddc604c694940b9b96c30e4b55eb1): perf score=1.000000
I20260812 06:19:01.916620  6733 maintenance_manager.cc:643] P 092432dd43d94cdf9339982fe9047346: MajorDeltaCompactionOp(237ddc604c694940b9b96c30e4b55eb1) complete. Timing: real 0.234s	user 0.166s	sys 0.064s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28836138,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":322,"lbm_read_time_us":17187,"lbm_reads_lt_1ms":672,"lbm_write_time_us":41645,"lbm_writes_lt_1ms":643,"mutex_wait_us":3,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3072,"update_count":3000}
I20260812 06:19:01.917513  6801 maintenance_manager.cc:419] P 092432dd43d94cdf9339982fe9047346: Scheduling FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1): perf score=14.095187
I20260812 06:19:01.990127  6733 maintenance_manager.cc:643] P 092432dd43d94cdf9339982fe9047346: FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1) complete. Timing: real 0.072s	user 0.047s	sys 0.024s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":32454,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:01.991062  6801 maintenance_manager.cc:419] P 092432dd43d94cdf9339982fe9047346: Scheduling FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1): perf score=2.188937
I20260812 06:19:02.010294  6733 maintenance_manager.cc:643] P 092432dd43d94cdf9339982fe9047346: FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1) complete. Timing: real 0.019s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5561,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:02.011052  6801 maintenance_manager.cc:419] P 092432dd43d94cdf9339982fe9047346: Scheduling MajorDeltaCompactionOp(237ddc604c694940b9b96c30e4b55eb1): perf score=1.000000
I20260812 06:19:02.225076  6733 maintenance_manager.cc:643] P 092432dd43d94cdf9339982fe9047346: MajorDeltaCompactionOp(237ddc604c694940b9b96c30e4b55eb1) complete. Timing: real 0.214s	user 0.150s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":436,"lbm_read_time_us":17702,"lbm_reads_lt_1ms":564,"lbm_write_time_us":35336,"lbm_writes_lt_1ms":543,"mutex_wait_us":28,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10112,"update_count":2500}
I20260812 06:19:02.226049  6801 maintenance_manager.cc:419] P 092432dd43d94cdf9339982fe9047346: Scheduling FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1): perf score=14.095187
I20260812 06:19:02.306367  6733 maintenance_manager.cc:643] P 092432dd43d94cdf9339982fe9047346: FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1) complete. Timing: real 0.080s	user 0.047s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":29897,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:02.307138  6801 maintenance_manager.cc:419] P 092432dd43d94cdf9339982fe9047346: Scheduling FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1): perf score=2.188937
I20260812 06:19:02.320616  6733 maintenance_manager.cc:643] P 092432dd43d94cdf9339982fe9047346: FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1) complete. Timing: real 0.013s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4855,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:02.321663  6801 maintenance_manager.cc:419] P 092432dd43d94cdf9339982fe9047346: Scheduling MajorDeltaCompactionOp(237ddc604c694940b9b96c30e4b55eb1): perf score=1.000000
I20260812 06:19:02.554839  6733 maintenance_manager.cc:643] P 092432dd43d94cdf9339982fe9047346: MajorDeltaCompactionOp(237ddc604c694940b9b96c30e4b55eb1) complete. Timing: real 0.233s	user 0.139s	sys 0.077s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1747,"lbm_read_time_us":15702,"lbm_reads_1-10_ms":1,"lbm_reads_lt_1ms":571,"lbm_write_time_us":38734,"lbm_writes_lt_1ms":543,"mutex_wait_us":417,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":28928,"update_count":2500}
I20260812 06:19:02.555621  6801 maintenance_manager.cc:419] P 092432dd43d94cdf9339982fe9047346: Scheduling FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1): perf score=14.095187
I20260812 06:19:02.635612  6733 maintenance_manager.cc:643] P 092432dd43d94cdf9339982fe9047346: FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1) complete. Timing: real 0.080s	user 0.043s	sys 0.028s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":27091,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:02.636464  6801 maintenance_manager.cc:419] P 092432dd43d94cdf9339982fe9047346: Scheduling FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1): perf score=2.188937
I20260812 06:19:02.651556  6733 maintenance_manager.cc:643] P 092432dd43d94cdf9339982fe9047346: FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5912,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:02.652233  6801 maintenance_manager.cc:419] P 092432dd43d94cdf9339982fe9047346: Scheduling MajorDeltaCompactionOp(237ddc604c694940b9b96c30e4b55eb1): perf score=1.000000
I20260812 06:19:02.898828  6733 maintenance_manager.cc:643] P 092432dd43d94cdf9339982fe9047346: MajorDeltaCompactionOp(237ddc604c694940b9b96c30e4b55eb1) complete. Timing: real 0.246s	user 0.165s	sys 0.074s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":503,"lbm_read_time_us":17700,"lbm_reads_lt_1ms":572,"lbm_write_time_us":40559,"lbm_writes_lt_1ms":543,"mutex_wait_us":25,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":67200,"update_count":2500}
I20260812 06:19:02.900002  6801 maintenance_manager.cc:419] P 092432dd43d94cdf9339982fe9047346: Scheduling FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1): perf score=14.095187
I20260812 06:19:02.984743  6733 maintenance_manager.cc:643] P 092432dd43d94cdf9339982fe9047346: FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1) complete. Timing: real 0.084s	user 0.040s	sys 0.032s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":26711,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:02.985656  6801 maintenance_manager.cc:419] P 092432dd43d94cdf9339982fe9047346: Scheduling FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1): perf score=2.188937
I20260812 06:19:03.008523  6733 maintenance_manager.cc:643] P 092432dd43d94cdf9339982fe9047346: FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1) complete. Timing: real 0.023s	user 0.006s	sys 0.013s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":8571,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:03.009320  6801 maintenance_manager.cc:419] P 092432dd43d94cdf9339982fe9047346: Scheduling MajorDeltaCompactionOp(237ddc604c694940b9b96c30e4b55eb1): perf score=1.000000
I20260812 06:19:03.248461  6733 maintenance_manager.cc:643] P 092432dd43d94cdf9339982fe9047346: MajorDeltaCompactionOp(237ddc604c694940b9b96c30e4b55eb1) complete. Timing: real 0.239s	user 0.150s	sys 0.080s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733725,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":404,"lbm_read_time_us":17329,"lbm_reads_lt_1ms":572,"lbm_write_time_us":39486,"lbm_writes_lt_1ms":543,"mutex_wait_us":98,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12160,"update_count":2500}
I20260812 06:19:03.249245  6801 maintenance_manager.cc:419] P 092432dd43d94cdf9339982fe9047346: Scheduling FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1): perf score=14.095187
I20260812 06:19:03.315225  6733 maintenance_manager.cc:643] P 092432dd43d94cdf9339982fe9047346: FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1) complete. Timing: real 0.066s	user 0.051s	sys 0.004s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24791,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:03.315910  6801 maintenance_manager.cc:419] P 092432dd43d94cdf9339982fe9047346: Scheduling FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1): perf score=2.188937
I20260812 06:19:03.341279  6733 maintenance_manager.cc:643] P 092432dd43d94cdf9339982fe9047346: FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1) complete. Timing: real 0.025s	user 0.010s	sys 0.015s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6396,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:03.342197  6801 maintenance_manager.cc:419] P 092432dd43d94cdf9339982fe9047346: Scheduling FlushMRSOp(237ddc604c694940b9b96c30e4b55eb1): perf score=1.000000
I20260812 06:19:03.381850  6733 maintenance_manager.cc:643] P 092432dd43d94cdf9339982fe9047346: FlushMRSOp(237ddc604c694940b9b96c30e4b55eb1) complete. Timing: real 0.039s	user 0.034s	sys 0.004s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":194,"dirs.run_cpu_time_us":500,"dirs.run_wall_time_us":2158,"drs_written":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2318,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:19:03.382961  6801 maintenance_manager.cc:419] P 092432dd43d94cdf9339982fe9047346: Scheduling LogGCOp(237ddc604c694940b9b96c30e4b55eb1): free 129320767 bytes of WAL
I20260812 06:19:03.383337  6733 log_reader.cc:385] T 237ddc604c694940b9b96c30e4b55eb1: removed 13 log segments from log reader
I20260812 06:19:03.383412  6733 log.cc:1079] T 237ddc604c694940b9b96c30e4b55eb1 P 092432dd43d94cdf9339982fe9047346: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/237ddc604c694940b9b96c30e4b55eb1/wal-000000027 (ops 126-130)
I20260812 06:19:03.383458  6733 log.cc:1079] T 237ddc604c694940b9b96c30e4b55eb1 P 092432dd43d94cdf9339982fe9047346: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/237ddc604c694940b9b96c30e4b55eb1/wal-000000028 (ops 131-134)
I20260812 06:19:03.383484  6733 log.cc:1079] T 237ddc604c694940b9b96c30e4b55eb1 P 092432dd43d94cdf9339982fe9047346: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/237ddc604c694940b9b96c30e4b55eb1/wal-000000029 (ops 135-139)
I20260812 06:19:03.383517  6733 log.cc:1079] T 237ddc604c694940b9b96c30e4b55eb1 P 092432dd43d94cdf9339982fe9047346: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/237ddc604c694940b9b96c30e4b55eb1/wal-000000030 (ops 140-144)
I20260812 06:19:03.383553  6733 log.cc:1079] T 237ddc604c694940b9b96c30e4b55eb1 P 092432dd43d94cdf9339982fe9047346: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/237ddc604c694940b9b96c30e4b55eb1/wal-000000031 (ops 145-149)
I20260812 06:19:03.383581  6733 log.cc:1079] T 237ddc604c694940b9b96c30e4b55eb1 P 092432dd43d94cdf9339982fe9047346: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/237ddc604c694940b9b96c30e4b55eb1/wal-000000032 (ops 150-154)
I20260812 06:19:03.383605  6733 log.cc:1079] T 237ddc604c694940b9b96c30e4b55eb1 P 092432dd43d94cdf9339982fe9047346: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/237ddc604c694940b9b96c30e4b55eb1/wal-000000033 (ops 155-159)
I20260812 06:19:03.383631  6733 log.cc:1079] T 237ddc604c694940b9b96c30e4b55eb1 P 092432dd43d94cdf9339982fe9047346: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/237ddc604c694940b9b96c30e4b55eb1/wal-000000034 (ops 160-164)
I20260812 06:19:03.383658  6733 log.cc:1079] T 237ddc604c694940b9b96c30e4b55eb1 P 092432dd43d94cdf9339982fe9047346: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/237ddc604c694940b9b96c30e4b55eb1/wal-000000035 (ops 165-168)
I20260812 06:19:03.383687  6733 log.cc:1079] T 237ddc604c694940b9b96c30e4b55eb1 P 092432dd43d94cdf9339982fe9047346: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/237ddc604c694940b9b96c30e4b55eb1/wal-000000036 (ops 169-173)
I20260812 06:19:03.383719  6733 log.cc:1079] T 237ddc604c694940b9b96c30e4b55eb1 P 092432dd43d94cdf9339982fe9047346: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/237ddc604c694940b9b96c30e4b55eb1/wal-000000037 (ops 174-178)
I20260812 06:19:03.383756  6733 log.cc:1079] T 237ddc604c694940b9b96c30e4b55eb1 P 092432dd43d94cdf9339982fe9047346: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/237ddc604c694940b9b96c30e4b55eb1/wal-000000038 (ops 179-183)
I20260812 06:19:03.383787  6733 log.cc:1079] T 237ddc604c694940b9b96c30e4b55eb1 P 092432dd43d94cdf9339982fe9047346: Deleting log segment in path: /tmp/dist-test-task1CJNxW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515530638234-6406-0/minicluster-data/ts-0-root/wals/237ddc604c694940b9b96c30e4b55eb1/wal-000000039 (ops 184-188)
I20260812 06:19:03.422712  6733 maintenance_manager.cc:643] P 092432dd43d94cdf9339982fe9047346: LogGCOp(237ddc604c694940b9b96c30e4b55eb1) complete. Timing: real 0.039s	user 0.000s	sys 0.038s Metrics: {}
I20260812 06:19:03.423350  6801 maintenance_manager.cc:419] P 092432dd43d94cdf9339982fe9047346: Scheduling UndoDeltaBlockGCOp(237ddc604c694940b9b96c30e4b55eb1): 493 bytes on disk
I20260812 06:19:03.423910  6733 maintenance_manager.cc:643] P 092432dd43d94cdf9339982fe9047346: UndoDeltaBlockGCOp(237ddc604c694940b9b96c30e4b55eb1) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":83,"lbm_reads_lt_1ms":4}
I20260812 06:19:03.424865  6801 maintenance_manager.cc:419] P 092432dd43d94cdf9339982fe9047346: Scheduling FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1): perf score=3.181125
I20260812 06:19:03.446645  6733 maintenance_manager.cc:643] P 092432dd43d94cdf9339982fe9047346: FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1) complete. Timing: real 0.021s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":7397,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:03.447322  6801 maintenance_manager.cc:419] P 092432dd43d94cdf9339982fe9047346: Scheduling FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1): perf score=2.188937
I20260812 06:19:03.460875  6733 maintenance_manager.cc:643] P 092432dd43d94cdf9339982fe9047346: FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1) complete. Timing: real 0.013s	user 0.006s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4849,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:03.461892  6801 maintenance_manager.cc:419] P 092432dd43d94cdf9339982fe9047346: Scheduling MajorDeltaCompactionOp(237ddc604c694940b9b96c30e4b55eb1): perf score=1.000000
I20260812 06:19:03.758205  6406 heavy-update-compaction-itest.cc:229] Time spent updating: real 6.015s	user 2.184s	sys 0.213s
I20260812 06:19:03.780737  6733 maintenance_manager.cc:643] P 092432dd43d94cdf9339982fe9047346: MajorDeltaCompactionOp(237ddc604c694940b9b96c30e4b55eb1) complete. Timing: real 0.318s	user 0.211s	sys 0.103s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32938772,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":20458,"lbm_reads_lt_1ms":770,"lbm_write_time_us":54492,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":3500}
I20260812 06:19:03.781824  6801 maintenance_manager.cc:419] P 092432dd43d94cdf9339982fe9047346: Scheduling FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1): perf score=18.063937
I20260812 06:19:03.837865  6733 maintenance_manager.cc:643] P 092432dd43d94cdf9339982fe9047346: FlushDeltaMemStoresOp(237ddc604c694940b9b96c30e4b55eb1) complete. Timing: real 0.056s	user 0.026s	sys 0.029s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":27614,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:03.838531  6801 maintenance_manager.cc:419] P 092432dd43d94cdf9339982fe9047346: Scheduling MajorDeltaCompactionOp(237ddc604c694940b9b96c30e4b55eb1): perf score=1.000000
I20260812 06:19:03.922856  6406 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.164s	user 0.003s	sys 0.000s
I20260812 06:19:03.923861  6406 tablet_server.cc:179] TabletServer@127.6.65.129:0 shutting down...
I20260812 06:19:04.026762  6733 maintenance_manager.cc:643] P 092432dd43d94cdf9339982fe9047346: MajorDeltaCompactionOp(237ddc604c694940b9b96c30e4b55eb1) complete. Timing: real 0.188s	user 0.131s	sys 0.055s Metrics: {"cfile_cache_miss":531,"cfile_cache_miss_bytes":24733608,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":820,"lbm_read_time_us":13256,"lbm_reads_lt_1ms":567,"lbm_write_time_us":40132,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":542,"mutex_wait_us":107,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":23680,"update_count":2500}
I20260812 06:19:04.027755  6406 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:04.028143  6406 tablet_replica.cc:333] T 237ddc604c694940b9b96c30e4b55eb1 P 092432dd43d94cdf9339982fe9047346: stopping tablet replica
I20260812 06:19:04.028333  6406 raft_consensus.cc:2243] T 237ddc604c694940b9b96c30e4b55eb1 P 092432dd43d94cdf9339982fe9047346 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:04.028569  6406 raft_consensus.cc:2272] T 237ddc604c694940b9b96c30e4b55eb1 P 092432dd43d94cdf9339982fe9047346 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:04.046530  6406 tablet_server.cc:196] TabletServer@127.6.65.129:0 shutdown complete.
I20260812 06:19:04.076232  6406 master.cc:562] Master@127.6.65.190:36897 shutting down...
I20260812 06:19:04.082499  6406 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 101a00e9145b4c059d4f0f9d1ced6cc6 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:04.082741  6406 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 101a00e9145b4c059d4f0f9d1ced6cc6 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:04.082816  6406 tablet_replica.cc:333] T 00000000000000000000000000000000 P 101a00e9145b4c059d4f0f9d1ced6cc6: stopping tablet replica
I20260812 06:19:04.097107  6406 master.cc:584] Master@127.6.65.190:36897 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (6727 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (13553 ms total)

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