[==========] 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:55.306923  6648 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.6.126.62:40035
I20260812 06:18:55.307969  6648 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:55.308593  6648 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:55.315655  6654 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:55.315692  6648 server_base.cc:1061] running on GCE node
W20260812 06:18:55.315886  6653 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:55.315958  6656 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:55.316592  6648 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:55.316684  6648 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:55.316710  6648 hybrid_clock.cc:648] HybridClock initialized: now 1786515535316709 us; error 0 us; skew 500 ppm
I20260812 06:18:55.318588  6648 webserver.cc:533] Webserver started at http://127.6.126.62:33683/ using document root <none> and password file <none>
I20260812 06:18:55.319111  6648 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:55.319170  6648 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:55.319388  6648 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:55.321022  6648 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535294106-6648-0/minicluster-data/master-0-root/instance:
uuid: "8f5c30d957bd40ce89f374e9b40c7eb2"
format_stamp: "Formatted at 2026-08-12 06:18:55 on dist-test-slave-zpfg"
I20260812 06:18:55.324594  6648 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.005s	sys 0.000s
I20260812 06:18:55.326723  6661 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:55.327804  6648 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:55.327924  6648 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535294106-6648-0/minicluster-data/master-0-root
uuid: "8f5c30d957bd40ce89f374e9b40c7eb2"
format_stamp: "Formatted at 2026-08-12 06:18:55 on dist-test-slave-zpfg"
I20260812 06:18:55.328011  6648 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535294106-6648-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535294106-6648-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535294106-6648-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:55.342519  6648 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:55.343145  6648 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:55.343288  6648 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:55.351258  6648 rpc_server.cc:307] RPC server started. Bound to: 127.6.126.62:40035
I20260812 06:18:55.351269  6715 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.6.126.62:40035 every 8 connection(s)
I20260812 06:18:55.353586  6716 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:55.359063  6716 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 8f5c30d957bd40ce89f374e9b40c7eb2: Bootstrap starting.
I20260812 06:18:55.361399  6716 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 8f5c30d957bd40ce89f374e9b40c7eb2: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:55.362432  6716 log.cc:826] T 00000000000000000000000000000000 P 8f5c30d957bd40ce89f374e9b40c7eb2: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:55.364163  6716 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 8f5c30d957bd40ce89f374e9b40c7eb2: No bootstrap required, opened a new log
I20260812 06:18:55.367121  6716 raft_consensus.cc:359] T 00000000000000000000000000000000 P 8f5c30d957bd40ce89f374e9b40c7eb2 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8f5c30d957bd40ce89f374e9b40c7eb2" member_type: VOTER }
I20260812 06:18:55.367327  6716 raft_consensus.cc:385] T 00000000000000000000000000000000 P 8f5c30d957bd40ce89f374e9b40c7eb2 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:55.367427  6716 raft_consensus.cc:740] T 00000000000000000000000000000000 P 8f5c30d957bd40ce89f374e9b40c7eb2 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 8f5c30d957bd40ce89f374e9b40c7eb2, State: Initialized, Role: FOLLOWER
I20260812 06:18:55.368053  6716 consensus_queue.cc:260] T 00000000000000000000000000000000 P 8f5c30d957bd40ce89f374e9b40c7eb2 [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: "8f5c30d957bd40ce89f374e9b40c7eb2" member_type: VOTER }
I20260812 06:18:55.368242  6716 raft_consensus.cc:399] T 00000000000000000000000000000000 P 8f5c30d957bd40ce89f374e9b40c7eb2 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:55.368324  6716 raft_consensus.cc:493] T 00000000000000000000000000000000 P 8f5c30d957bd40ce89f374e9b40c7eb2 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:55.368467  6716 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 8f5c30d957bd40ce89f374e9b40c7eb2 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:55.369323  6716 raft_consensus.cc:515] T 00000000000000000000000000000000 P 8f5c30d957bd40ce89f374e9b40c7eb2 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8f5c30d957bd40ce89f374e9b40c7eb2" member_type: VOTER }
I20260812 06:18:55.369791  6716 leader_election.cc:304] T 00000000000000000000000000000000 P 8f5c30d957bd40ce89f374e9b40c7eb2 [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: 8f5c30d957bd40ce89f374e9b40c7eb2; no voters: 
I20260812 06:18:55.370146  6716 leader_election.cc:290] T 00000000000000000000000000000000 P 8f5c30d957bd40ce89f374e9b40c7eb2 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:55.370299  6719 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 8f5c30d957bd40ce89f374e9b40c7eb2 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:55.370615  6719 raft_consensus.cc:697] T 00000000000000000000000000000000 P 8f5c30d957bd40ce89f374e9b40c7eb2 [term 1 LEADER]: Becoming Leader. State: Replica: 8f5c30d957bd40ce89f374e9b40c7eb2, State: Running, Role: LEADER
I20260812 06:18:55.371032  6719 consensus_queue.cc:237] T 00000000000000000000000000000000 P 8f5c30d957bd40ce89f374e9b40c7eb2 [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: "8f5c30d957bd40ce89f374e9b40c7eb2" member_type: VOTER }
I20260812 06:18:55.371284  6716 sys_catalog.cc:565] T 00000000000000000000000000000000 P 8f5c30d957bd40ce89f374e9b40c7eb2 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:55.373026  6721 sys_catalog.cc:455] T 00000000000000000000000000000000 P 8f5c30d957bd40ce89f374e9b40c7eb2 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "8f5c30d957bd40ce89f374e9b40c7eb2" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8f5c30d957bd40ce89f374e9b40c7eb2" member_type: VOTER } }
I20260812 06:18:55.373147  6721 sys_catalog.cc:458] T 00000000000000000000000000000000 P 8f5c30d957bd40ce89f374e9b40c7eb2 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:55.373098  6722 sys_catalog.cc:455] T 00000000000000000000000000000000 P 8f5c30d957bd40ce89f374e9b40c7eb2 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 8f5c30d957bd40ce89f374e9b40c7eb2. Latest consensus state: current_term: 1 leader_uuid: "8f5c30d957bd40ce89f374e9b40c7eb2" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8f5c30d957bd40ce89f374e9b40c7eb2" member_type: VOTER } }
I20260812 06:18:55.373204  6722 sys_catalog.cc:458] T 00000000000000000000000000000000 P 8f5c30d957bd40ce89f374e9b40c7eb2 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:55.373575  6732 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:55.373718  6648 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:55.375981  6732 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:55.380645  6732 catalog_manager.cc:1383] Generated new cluster ID: 19efefc8fbc742e28395f0bc230b031c
I20260812 06:18:55.380719  6732 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:55.395285  6732 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:55.396509  6732 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:55.405023  6732 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 8f5c30d957bd40ce89f374e9b40c7eb2: Generated new TSK 0
I20260812 06:18:55.405893  6732 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:55.438675  6648 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:55.441742  6742 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:55.441823  6743 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:55.441954  6745 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:55.442049  6648 server_base.cc:1061] running on GCE node
I20260812 06:18:55.442230  6648 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:55.442307  6648 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:55.442333  6648 hybrid_clock.cc:648] HybridClock initialized: now 1786515535442333 us; error 0 us; skew 500 ppm
I20260812 06:18:55.443322  6648 webserver.cc:533] Webserver started at http://127.6.126.1:43699/ using document root <none> and password file <none>
I20260812 06:18:55.443496  6648 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:55.443572  6648 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:55.443655  6648 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:55.444048  6648 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535294106-6648-0/minicluster-data/ts-0-root/instance:
uuid: "0089bb36467f40ebac4b5b3a3418382f"
format_stamp: "Formatted at 2026-08-12 06:18:55 on dist-test-slave-zpfg"
I20260812 06:18:55.445571  6648 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:55.446609  6751 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:55.446879  6648 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:55.446941  6648 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535294106-6648-0/minicluster-data/ts-0-root
uuid: "0089bb36467f40ebac4b5b3a3418382f"
format_stamp: "Formatted at 2026-08-12 06:18:55 on dist-test-slave-zpfg"
I20260812 06:18:55.447031  6648 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535294106-6648-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535294106-6648-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535294106-6648-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:55.462838  6648 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:55.463348  6648 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:55.463891  6648 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:55.464865  6648 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:55.464919  6648 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:55.464963  6648 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:55.465021  6648 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:55.472421  6648 rpc_server.cc:307] RPC server started. Bound to: 127.6.126.1:39001
I20260812 06:18:55.472443  6823 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.6.126.1:39001 every 8 connection(s)
I20260812 06:18:55.487007  6824 heartbeater.cc:344] Connected to a master server at 127.6.126.62:40035
I20260812 06:18:55.487294  6824 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:55.487852  6824 heartbeater.cc:507] Master 127.6.126.62:40035 requested a full tablet report, sending...
I20260812 06:18:55.489279  6679 ts_manager.cc:194] Registered new tserver with Master: 0089bb36467f40ebac4b5b3a3418382f (127.6.126.1:39001)
I20260812 06:18:55.489933  6648 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.016731277s
I20260812 06:18:55.490582  6679 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:44582
I20260812 06:18:55.499960  6679 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:44598:
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:55.514497  6782 tablet_service.cc:1511] Processing CreateTablet for tablet d64237f60ebb455a95f33ecd6fbaa867 (DEFAULT_TABLE table=heavy-update-compaction-test [id=7775169bf6fc4a9ebcec01ad4db61e12]), partition=
I20260812 06:18:55.514962  6782 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet d64237f60ebb455a95f33ecd6fbaa867. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:55.517334  6837 tablet_bootstrap.cc:492] T d64237f60ebb455a95f33ecd6fbaa867 P 0089bb36467f40ebac4b5b3a3418382f: Bootstrap starting.
I20260812 06:18:55.518270  6837 tablet_bootstrap.cc:654] T d64237f60ebb455a95f33ecd6fbaa867 P 0089bb36467f40ebac4b5b3a3418382f: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:55.519873  6837 tablet_bootstrap.cc:492] T d64237f60ebb455a95f33ecd6fbaa867 P 0089bb36467f40ebac4b5b3a3418382f: No bootstrap required, opened a new log
I20260812 06:18:55.520004  6837 ts_tablet_manager.cc:1403] T d64237f60ebb455a95f33ecd6fbaa867 P 0089bb36467f40ebac4b5b3a3418382f: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:18:55.520594  6837 raft_consensus.cc:359] T d64237f60ebb455a95f33ecd6fbaa867 P 0089bb36467f40ebac4b5b3a3418382f [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0089bb36467f40ebac4b5b3a3418382f" member_type: VOTER last_known_addr { host: "127.6.126.1" port: 39001 } }
I20260812 06:18:55.520793  6837 raft_consensus.cc:385] T d64237f60ebb455a95f33ecd6fbaa867 P 0089bb36467f40ebac4b5b3a3418382f [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:55.520872  6837 raft_consensus.cc:740] T d64237f60ebb455a95f33ecd6fbaa867 P 0089bb36467f40ebac4b5b3a3418382f [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 0089bb36467f40ebac4b5b3a3418382f, State: Initialized, Role: FOLLOWER
I20260812 06:18:55.521039  6837 consensus_queue.cc:260] T d64237f60ebb455a95f33ecd6fbaa867 P 0089bb36467f40ebac4b5b3a3418382f [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: "0089bb36467f40ebac4b5b3a3418382f" member_type: VOTER last_known_addr { host: "127.6.126.1" port: 39001 } }
I20260812 06:18:55.521148  6837 raft_consensus.cc:399] T d64237f60ebb455a95f33ecd6fbaa867 P 0089bb36467f40ebac4b5b3a3418382f [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:55.521198  6837 raft_consensus.cc:493] T d64237f60ebb455a95f33ecd6fbaa867 P 0089bb36467f40ebac4b5b3a3418382f [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:55.521250  6837 raft_consensus.cc:3060] T d64237f60ebb455a95f33ecd6fbaa867 P 0089bb36467f40ebac4b5b3a3418382f [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:55.522004  6837 raft_consensus.cc:515] T d64237f60ebb455a95f33ecd6fbaa867 P 0089bb36467f40ebac4b5b3a3418382f [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0089bb36467f40ebac4b5b3a3418382f" member_type: VOTER last_known_addr { host: "127.6.126.1" port: 39001 } }
I20260812 06:18:55.522156  6837 leader_election.cc:304] T d64237f60ebb455a95f33ecd6fbaa867 P 0089bb36467f40ebac4b5b3a3418382f [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: 0089bb36467f40ebac4b5b3a3418382f; no voters: 
I20260812 06:18:55.522449  6837 leader_election.cc:290] T d64237f60ebb455a95f33ecd6fbaa867 P 0089bb36467f40ebac4b5b3a3418382f [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:55.522548  6841 raft_consensus.cc:2804] T d64237f60ebb455a95f33ecd6fbaa867 P 0089bb36467f40ebac4b5b3a3418382f [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:55.522724  6841 raft_consensus.cc:697] T d64237f60ebb455a95f33ecd6fbaa867 P 0089bb36467f40ebac4b5b3a3418382f [term 1 LEADER]: Becoming Leader. State: Replica: 0089bb36467f40ebac4b5b3a3418382f, State: Running, Role: LEADER
I20260812 06:18:55.522840  6837 ts_tablet_manager.cc:1434] T d64237f60ebb455a95f33ecd6fbaa867 P 0089bb36467f40ebac4b5b3a3418382f: Time spent starting tablet: real 0.003s	user 0.001s	sys 0.002s
I20260812 06:18:55.522931  6841 consensus_queue.cc:237] T d64237f60ebb455a95f33ecd6fbaa867 P 0089bb36467f40ebac4b5b3a3418382f [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: "0089bb36467f40ebac4b5b3a3418382f" member_type: VOTER last_known_addr { host: "127.6.126.1" port: 39001 } }
I20260812 06:18:55.523147  6824 heartbeater.cc:499] Master 127.6.126.62:40035 was elected leader, sending a full tablet report...
I20260812 06:18:55.525748  6679 catalog_manager.cc:5719] T d64237f60ebb455a95f33ecd6fbaa867 P 0089bb36467f40ebac4b5b3a3418382f reported cstate change: term changed from 0 to 1, leader changed from <none> to 0089bb36467f40ebac4b5b3a3418382f (127.6.126.1). New cstate: current_term: 1 leader_uuid: "0089bb36467f40ebac4b5b3a3418382f" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0089bb36467f40ebac4b5b3a3418382f" member_type: VOTER last_known_addr { host: "127.6.126.1" port: 39001 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:55.593067  6648 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.061s	user 0.027s	sys 0.003s
I20260812 06:18:55.723881  6826 maintenance_manager.cc:419] P 0089bb36467f40ebac4b5b3a3418382f: Scheduling FlushMRSOp(d64237f60ebb455a95f33ecd6fbaa867): perf score=15.086190
I20260812 06:18:55.892282  6757 maintenance_manager.cc:643] P 0089bb36467f40ebac4b5b3a3418382f: FlushMRSOp(d64237f60ebb455a95f33ecd6fbaa867) complete. Timing: real 0.168s	user 0.112s	sys 0.047s Metrics: {"bytes_written":13538208,"cfile_init":1,"compiler_manager_pool.queue_time_us":195,"delete_count":0,"dirs.queue_time_us":55,"dirs.run_cpu_time_us":239,"dirs.run_wall_time_us":1136,"drs_written":1,"lbm_read_time_us":72,"lbm_reads_lt_1ms":4,"lbm_write_time_us":37209,"lbm_writes_lt_1ms":687,"mutex_wait_us":6527,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"spinlock_wait_cycles":361344,"thread_start_us":117,"threads_started":1,"update_count":1650}
I20260812 06:18:55.893822  6826 maintenance_manager.cc:419] P 0089bb36467f40ebac4b5b3a3418382f: Scheduling LogGCOp(d64237f60ebb455a95f33ecd6fbaa867): free 20290830 bytes of WAL
I20260812 06:18:55.894223  6757 log_reader.cc:385] T d64237f60ebb455a95f33ecd6fbaa867: removed 2 log segments from log reader
I20260812 06:18:55.894299  6757 log.cc:1079] T d64237f60ebb455a95f33ecd6fbaa867 P 0089bb36467f40ebac4b5b3a3418382f: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/d64237f60ebb455a95f33ecd6fbaa867/wal-000000001 (ops 1-6)
I20260812 06:18:55.894393  6757 log.cc:1079] T d64237f60ebb455a95f33ecd6fbaa867 P 0089bb36467f40ebac4b5b3a3418382f: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/d64237f60ebb455a95f33ecd6fbaa867/wal-000000002 (ops 7-10)
I20260812 06:18:55.900642  6757 maintenance_manager.cc:643] P 0089bb36467f40ebac4b5b3a3418382f: LogGCOp(d64237f60ebb455a95f33ecd6fbaa867) complete. Timing: real 0.007s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:18:55.901175  6826 maintenance_manager.cc:419] P 0089bb36467f40ebac4b5b3a3418382f: Scheduling UndoDeltaBlockGCOp(d64237f60ebb455a95f33ecd6fbaa867): 12308959 bytes on disk
I20260812 06:18:55.901791  6757 maintenance_manager.cc:643] P 0089bb36467f40ebac4b5b3a3418382f: UndoDeltaBlockGCOp(d64237f60ebb455a95f33ecd6fbaa867) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4}
I20260812 06:18:55.902527  6826 maintenance_manager.cc:419] P 0089bb36467f40ebac4b5b3a3418382f: Scheduling FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867): perf score=2.188937
I20260812 06:18:55.917616  6757 maintenance_manager.cc:643] P 0089bb36467f40ebac4b5b3a3418382f: FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867) complete. Timing: real 0.015s	user 0.005s	sys 0.005s Metrics: {"bytes_written":3282159,"delete_count":0,"lbm_write_time_us":4468,"lbm_writes_lt_1ms":83,"reinsert_count":0,"update_count":400}
I20260812 06:18:55.918123  6826 maintenance_manager.cc:419] P 0089bb36467f40ebac4b5b3a3418382f: Scheduling FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867): perf score=2.188937
I20260812 06:18:55.932987  6757 maintenance_manager.cc:643] P 0089bb36467f40ebac4b5b3a3418382f: FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867) complete. Timing: real 0.015s	user 0.010s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5546,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:55.933487  6826 maintenance_manager.cc:419] P 0089bb36467f40ebac4b5b3a3418382f: Scheduling MajorDeltaCompactionOp(d64237f60ebb455a95f33ecd6fbaa867): perf score=1.000000
I20260812 06:18:56.106678  6757 maintenance_manager.cc:643] P 0089bb36467f40ebac4b5b3a3418382f: MajorDeltaCompactionOp(d64237f60ebb455a95f33ecd6fbaa867) complete. Timing: real 0.173s	user 0.119s	sys 0.052s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733807,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":941,"lbm_read_time_us":10366,"lbm_reads_lt_1ms":569,"lbm_write_time_us":32415,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1536,"thread_start_us":344,"threads_started":5,"update_count":2500}
I20260812 06:18:56.107249  6826 maintenance_manager.cc:419] P 0089bb36467f40ebac4b5b3a3418382f: Scheduling FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867): perf score=10.126437
I20260812 06:18:56.144188  6757 maintenance_manager.cc:643] P 0089bb36467f40ebac4b5b3a3418382f: FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867) complete. Timing: real 0.037s	user 0.031s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16096,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:56.144822  6826 maintenance_manager.cc:419] P 0089bb36467f40ebac4b5b3a3418382f: Scheduling FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867): perf score=2.188937
I20260812 06:18:56.160209  6757 maintenance_manager.cc:643] P 0089bb36467f40ebac4b5b3a3418382f: FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6135,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:56.160728  6826 maintenance_manager.cc:419] P 0089bb36467f40ebac4b5b3a3418382f: Scheduling MajorDeltaCompactionOp(d64237f60ebb455a95f33ecd6fbaa867): perf score=1.000000
I20260812 06:18:56.290961  6757 maintenance_manager.cc:643] P 0089bb36467f40ebac4b5b3a3418382f: MajorDeltaCompactionOp(d64237f60ebb455a95f33ecd6fbaa867) complete. Timing: real 0.130s	user 0.102s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1270,"lbm_read_time_us":8260,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24345,"lbm_writes_lt_1ms":443,"mutex_wait_us":324,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":58240,"update_count":2000}
I20260812 06:18:56.291734  6826 maintenance_manager.cc:419] P 0089bb36467f40ebac4b5b3a3418382f: Scheduling FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867): perf score=10.126437
I20260812 06:18:56.344856  6757 maintenance_manager.cc:643] P 0089bb36467f40ebac4b5b3a3418382f: FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867) complete. Timing: real 0.053s	user 0.037s	sys 0.012s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":24969,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":300,"reinsert_count":0,"update_count":1500}
I20260812 06:18:56.345346  6826 maintenance_manager.cc:419] P 0089bb36467f40ebac4b5b3a3418382f: Scheduling FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867): perf score=2.188937
I20260812 06:18:56.358186  6757 maintenance_manager.cc:643] P 0089bb36467f40ebac4b5b3a3418382f: FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867) complete. Timing: real 0.013s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4576,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:56.358790  6826 maintenance_manager.cc:419] P 0089bb36467f40ebac4b5b3a3418382f: Scheduling MajorDeltaCompactionOp(d64237f60ebb455a95f33ecd6fbaa867): perf score=1.000000
I20260812 06:18:56.506485  6757 maintenance_manager.cc:643] P 0089bb36467f40ebac4b5b3a3418382f: MajorDeltaCompactionOp(d64237f60ebb455a95f33ecd6fbaa867) complete. Timing: real 0.147s	user 0.117s	sys 0.030s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":460,"lbm_read_time_us":8235,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29742,"lbm_writes_lt_1ms":443,"mutex_wait_us":55,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":29696,"update_count":2000}
I20260812 06:18:56.507288  6826 maintenance_manager.cc:419] P 0089bb36467f40ebac4b5b3a3418382f: Scheduling FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867): perf score=10.126437
I20260812 06:18:56.560686  6757 maintenance_manager.cc:643] P 0089bb36467f40ebac4b5b3a3418382f: FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867) complete. Timing: real 0.053s	user 0.027s	sys 0.024s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20240,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:56.561244  6826 maintenance_manager.cc:419] P 0089bb36467f40ebac4b5b3a3418382f: Scheduling FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867): perf score=2.188937
I20260812 06:18:56.572402  6757 maintenance_manager.cc:643] P 0089bb36467f40ebac4b5b3a3418382f: FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4272,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:56.572961  6826 maintenance_manager.cc:419] P 0089bb36467f40ebac4b5b3a3418382f: Scheduling MajorDeltaCompactionOp(d64237f60ebb455a95f33ecd6fbaa867): perf score=1.000000
I20260812 06:18:56.727151  6757 maintenance_manager.cc:643] P 0089bb36467f40ebac4b5b3a3418382f: MajorDeltaCompactionOp(d64237f60ebb455a95f33ecd6fbaa867) complete. Timing: real 0.154s	user 0.102s	sys 0.052s 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":951,"lbm_read_time_us":11119,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24784,"lbm_writes_lt_1ms":443,"mutex_wait_us":322,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":40704,"update_count":2000}
I20260812 06:18:56.727768  6826 maintenance_manager.cc:419] P 0089bb36467f40ebac4b5b3a3418382f: Scheduling FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867): perf score=10.126437
I20260812 06:18:56.764808  6757 maintenance_manager.cc:643] P 0089bb36467f40ebac4b5b3a3418382f: FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867) complete. Timing: real 0.037s	user 0.018s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16075,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:56.765446  6826 maintenance_manager.cc:419] P 0089bb36467f40ebac4b5b3a3418382f: Scheduling MajorDeltaCompactionOp(d64237f60ebb455a95f33ecd6fbaa867): perf score=1.000000
I20260812 06:18:56.881237  6757 maintenance_manager.cc:643] P 0089bb36467f40ebac4b5b3a3418382f: MajorDeltaCompactionOp(d64237f60ebb455a95f33ecd6fbaa867) complete. Timing: real 0.116s	user 0.084s	sys 0.032s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16528781,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":215,"lbm_read_time_us":7946,"lbm_reads_lt_1ms":363,"lbm_write_time_us":22306,"lbm_writes_lt_1ms":343,"mutex_wait_us":57,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":67456,"update_count":1500}
I20260812 06:18:56.882088  6826 maintenance_manager.cc:419] P 0089bb36467f40ebac4b5b3a3418382f: Scheduling FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867): perf score=10.126437
I20260812 06:18:56.928424  6757 maintenance_manager.cc:643] P 0089bb36467f40ebac4b5b3a3418382f: FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867) complete. Timing: real 0.046s	user 0.024s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18016,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:56.928920  6826 maintenance_manager.cc:419] P 0089bb36467f40ebac4b5b3a3418382f: Scheduling MajorDeltaCompactionOp(d64237f60ebb455a95f33ecd6fbaa867): perf score=1.000000
I20260812 06:18:57.032688  6757 maintenance_manager.cc:643] P 0089bb36467f40ebac4b5b3a3418382f: MajorDeltaCompactionOp(d64237f60ebb455a95f33ecd6fbaa867) complete. Timing: real 0.104s	user 0.079s	sys 0.024s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16528781,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":799,"lbm_read_time_us":5938,"lbm_reads_lt_1ms":363,"lbm_write_time_us":20983,"lbm_writes_lt_1ms":343,"mutex_wait_us":328,"peak_mem_usage":38262756,"reinsert_count":0,"update_count":1500}
I20260812 06:18:57.033391  6826 maintenance_manager.cc:419] P 0089bb36467f40ebac4b5b3a3418382f: Scheduling FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867): perf score=10.126437
I20260812 06:18:57.080890  6757 maintenance_manager.cc:643] P 0089bb36467f40ebac4b5b3a3418382f: FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867) complete. Timing: real 0.047s	user 0.012s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16424,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:57.081504  6826 maintenance_manager.cc:419] P 0089bb36467f40ebac4b5b3a3418382f: Scheduling FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867): perf score=2.188937
I20260812 06:18:57.095775  6757 maintenance_manager.cc:643] P 0089bb36467f40ebac4b5b3a3418382f: FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867) complete. Timing: real 0.014s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5642,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:57.096264  6826 maintenance_manager.cc:419] P 0089bb36467f40ebac4b5b3a3418382f: Scheduling MajorDeltaCompactionOp(d64237f60ebb455a95f33ecd6fbaa867): perf score=1.000000
I20260812 06:18:57.231033  6757 maintenance_manager.cc:643] P 0089bb36467f40ebac4b5b3a3418382f: MajorDeltaCompactionOp(d64237f60ebb455a95f33ecd6fbaa867) complete. Timing: real 0.135s	user 0.104s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":219,"lbm_read_time_us":8530,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26723,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":17664,"update_count":2000}
I20260812 06:18:57.231535  6826 maintenance_manager.cc:419] P 0089bb36467f40ebac4b5b3a3418382f: Scheduling FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867): perf score=10.126437
I20260812 06:18:57.273276  6757 maintenance_manager.cc:643] P 0089bb36467f40ebac4b5b3a3418382f: FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867) complete. Timing: real 0.042s	user 0.023s	sys 0.012s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16034,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:57.273947  6826 maintenance_manager.cc:419] P 0089bb36467f40ebac4b5b3a3418382f: Scheduling FlushMRSOp(d64237f60ebb455a95f33ecd6fbaa867): perf score=1.000000
I20260812 06:18:57.323693  6757 maintenance_manager.cc:643] P 0089bb36467f40ebac4b5b3a3418382f: FlushMRSOp(d64237f60ebb455a95f33ecd6fbaa867) complete. Timing: real 0.050s	user 0.028s	sys 0.002s Metrics: {"bytes_written":1275444,"cfile_init":1,"dirs.queue_time_us":58,"dirs.run_cpu_time_us":258,"dirs.run_wall_time_us":1713,"drs_written":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2623,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:57.324715  6826 maintenance_manager.cc:419] P 0089bb36467f40ebac4b5b3a3418382f: Scheduling LogGCOp(d64237f60ebb455a95f33ecd6fbaa867): free 121006435 bytes of WAL
I20260812 06:18:57.325001  6757 log_reader.cc:385] T d64237f60ebb455a95f33ecd6fbaa867: removed 12 log segments from log reader
I20260812 06:18:57.325073  6757 log.cc:1079] T d64237f60ebb455a95f33ecd6fbaa867 P 0089bb36467f40ebac4b5b3a3418382f: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/d64237f60ebb455a95f33ecd6fbaa867/wal-000000003 (ops 11-15)
I20260812 06:18:57.325129  6757 log.cc:1079] T d64237f60ebb455a95f33ecd6fbaa867 P 0089bb36467f40ebac4b5b3a3418382f: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/d64237f60ebb455a95f33ecd6fbaa867/wal-000000004 (ops 16-20)
I20260812 06:18:57.325168  6757 log.cc:1079] T d64237f60ebb455a95f33ecd6fbaa867 P 0089bb36467f40ebac4b5b3a3418382f: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/d64237f60ebb455a95f33ecd6fbaa867/wal-000000005 (ops 21-25)
I20260812 06:18:57.325204  6757 log.cc:1079] T d64237f60ebb455a95f33ecd6fbaa867 P 0089bb36467f40ebac4b5b3a3418382f: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/d64237f60ebb455a95f33ecd6fbaa867/wal-000000006 (ops 26-30)
I20260812 06:18:57.325242  6757 log.cc:1079] T d64237f60ebb455a95f33ecd6fbaa867 P 0089bb36467f40ebac4b5b3a3418382f: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/d64237f60ebb455a95f33ecd6fbaa867/wal-000000007 (ops 31-35)
I20260812 06:18:57.325281  6757 log.cc:1079] T d64237f60ebb455a95f33ecd6fbaa867 P 0089bb36467f40ebac4b5b3a3418382f: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/d64237f60ebb455a95f33ecd6fbaa867/wal-000000008 (ops 36-40)
I20260812 06:18:57.325320  6757 log.cc:1079] T d64237f60ebb455a95f33ecd6fbaa867 P 0089bb36467f40ebac4b5b3a3418382f: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/d64237f60ebb455a95f33ecd6fbaa867/wal-000000009 (ops 41-45)
I20260812 06:18:57.325359  6757 log.cc:1079] T d64237f60ebb455a95f33ecd6fbaa867 P 0089bb36467f40ebac4b5b3a3418382f: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/d64237f60ebb455a95f33ecd6fbaa867/wal-000000010 (ops 46-50)
I20260812 06:18:57.325398  6757 log.cc:1079] T d64237f60ebb455a95f33ecd6fbaa867 P 0089bb36467f40ebac4b5b3a3418382f: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/d64237f60ebb455a95f33ecd6fbaa867/wal-000000011 (ops 51-54)
I20260812 06:18:57.325438  6757 log.cc:1079] T d64237f60ebb455a95f33ecd6fbaa867 P 0089bb36467f40ebac4b5b3a3418382f: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/d64237f60ebb455a95f33ecd6fbaa867/wal-000000012 (ops 55-59)
I20260812 06:18:57.325475  6757 log.cc:1079] T d64237f60ebb455a95f33ecd6fbaa867 P 0089bb36467f40ebac4b5b3a3418382f: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/d64237f60ebb455a95f33ecd6fbaa867/wal-000000013 (ops 60-64)
I20260812 06:18:57.325512  6757 log.cc:1079] T d64237f60ebb455a95f33ecd6fbaa867 P 0089bb36467f40ebac4b5b3a3418382f: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/d64237f60ebb455a95f33ecd6fbaa867/wal-000000014 (ops 65-69)
I20260812 06:18:57.351557  6757 maintenance_manager.cc:643] P 0089bb36467f40ebac4b5b3a3418382f: LogGCOp(d64237f60ebb455a95f33ecd6fbaa867) complete. Timing: real 0.027s	user 0.003s	sys 0.023s Metrics: {}
I20260812 06:18:57.351991  6826 maintenance_manager.cc:419] P 0089bb36467f40ebac4b5b3a3418382f: Scheduling UndoDeltaBlockGCOp(d64237f60ebb455a95f33ecd6fbaa867): 482 bytes on disk
I20260812 06:18:57.352432  6757 maintenance_manager.cc:643] P 0089bb36467f40ebac4b5b3a3418382f: UndoDeltaBlockGCOp(d64237f60ebb455a95f33ecd6fbaa867) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4}
I20260812 06:18:57.352903  6826 maintenance_manager.cc:419] P 0089bb36467f40ebac4b5b3a3418382f: Scheduling FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867): perf score=7.149875
I20260812 06:18:57.376423  6757 maintenance_manager.cc:643] P 0089bb36467f40ebac4b5b3a3418382f: FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867) complete. Timing: real 0.023s	user 0.009s	sys 0.012s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":10037,"lbm_writes_lt_1ms":213,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":1050}
I20260812 06:18:57.377067  6826 maintenance_manager.cc:419] P 0089bb36467f40ebac4b5b3a3418382f: Scheduling FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867): perf score=2.188937
I20260812 06:18:57.388815  6757 maintenance_manager.cc:643] P 0089bb36467f40ebac4b5b3a3418382f: FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4201,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:57.389274  6826 maintenance_manager.cc:419] P 0089bb36467f40ebac4b5b3a3418382f: Scheduling MajorDeltaCompactionOp(d64237f60ebb455a95f33ecd6fbaa867): perf score=1.000000
I20260812 06:18:57.570873  6757 maintenance_manager.cc:643] P 0089bb36467f40ebac4b5b3a3418382f: MajorDeltaCompactionOp(d64237f60ebb455a95f33ecd6fbaa867) complete. Timing: real 0.181s	user 0.144s	sys 0.031s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28836246,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":7830,"lbm_read_time_us":12131,"lbm_reads_lt_1ms":673,"lbm_write_time_us":37121,"lbm_writes_lt_1ms":643,"mutex_wait_us":2493,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3584,"thread_start_us":86,"threads_started":1,"update_count":3000}
I20260812 06:18:57.571583  6826 maintenance_manager.cc:419] P 0089bb36467f40ebac4b5b3a3418382f: Scheduling FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867): perf score=14.095187
I20260812 06:18:57.618170  6757 maintenance_manager.cc:643] P 0089bb36467f40ebac4b5b3a3418382f: FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867) complete. Timing: real 0.046s	user 0.021s	sys 0.020s Metrics: {"bytes_written":16409906,"delete_count":0,"lbm_write_time_us":19475,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:57.618803  6826 maintenance_manager.cc:419] P 0089bb36467f40ebac4b5b3a3418382f: Scheduling FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867): perf score=2.188937
I20260812 06:18:57.630304  6757 maintenance_manager.cc:643] P 0089bb36467f40ebac4b5b3a3418382f: FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4026,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:57.630842  6826 maintenance_manager.cc:419] P 0089bb36467f40ebac4b5b3a3418382f: Scheduling MajorDeltaCompactionOp(d64237f60ebb455a95f33ecd6fbaa867): perf score=1.000000
I20260812 06:18:57.771912  6757 maintenance_manager.cc:643] P 0089bb36467f40ebac4b5b3a3418382f: MajorDeltaCompactionOp(d64237f60ebb455a95f33ecd6fbaa867) complete. Timing: real 0.141s	user 0.112s	sys 0.028s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733728,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":863,"lbm_read_time_us":9551,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29771,"lbm_writes_lt_1ms":543,"mutex_wait_us":193,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11136,"update_count":2500}
I20260812 06:18:57.772544  6826 maintenance_manager.cc:419] P 0089bb36467f40ebac4b5b3a3418382f: Scheduling FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867): perf score=11.118625
I20260812 06:18:57.808359  6757 maintenance_manager.cc:643] P 0089bb36467f40ebac4b5b3a3418382f: FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867) complete. Timing: real 0.036s	user 0.024s	sys 0.009s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14716,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:57.809017  6826 maintenance_manager.cc:419] P 0089bb36467f40ebac4b5b3a3418382f: Scheduling FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867): perf score=2.188937
I20260812 06:18:57.831794  6757 maintenance_manager.cc:643] P 0089bb36467f40ebac4b5b3a3418382f: FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867) complete. Timing: real 0.022s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5027,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:57.832367  6826 maintenance_manager.cc:419] P 0089bb36467f40ebac4b5b3a3418382f: Scheduling FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867): perf score=2.188937
I20260812 06:18:57.842737  6757 maintenance_manager.cc:643] P 0089bb36467f40ebac4b5b3a3418382f: FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867) complete. Timing: real 0.010s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3926,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:57.843185  6826 maintenance_manager.cc:419] P 0089bb36467f40ebac4b5b3a3418382f: Scheduling MajorDeltaCompactionOp(d64237f60ebb455a95f33ecd6fbaa867): perf score=1.000000
I20260812 06:18:57.987067  6757 maintenance_manager.cc:643] P 0089bb36467f40ebac4b5b3a3418382f: MajorDeltaCompactionOp(d64237f60ebb455a95f33ecd6fbaa867) complete. Timing: real 0.144s	user 0.101s	sys 0.040s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733834,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":278,"lbm_read_time_us":10081,"lbm_reads_lt_1ms":573,"lbm_write_time_us":28768,"lbm_writes_lt_1ms":543,"mutex_wait_us":67,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:57.987890  6826 maintenance_manager.cc:419] P 0089bb36467f40ebac4b5b3a3418382f: Scheduling FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867): perf score=11.118625
I20260812 06:18:58.021721  6757 maintenance_manager.cc:643] P 0089bb36467f40ebac4b5b3a3418382f: FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867) complete. Timing: real 0.034s	user 0.022s	sys 0.008s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14542,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:58.022431  6826 maintenance_manager.cc:419] P 0089bb36467f40ebac4b5b3a3418382f: Scheduling FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867): perf score=2.188937
I20260812 06:18:58.046033  6757 maintenance_manager.cc:643] P 0089bb36467f40ebac4b5b3a3418382f: FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867) complete. Timing: real 0.023s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5230,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:58.046679  6826 maintenance_manager.cc:419] P 0089bb36467f40ebac4b5b3a3418382f: Scheduling FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867): perf score=2.188937
I20260812 06:18:58.056977  6757 maintenance_manager.cc:643] P 0089bb36467f40ebac4b5b3a3418382f: FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3828,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:58.057497  6826 maintenance_manager.cc:419] P 0089bb36467f40ebac4b5b3a3418382f: Scheduling MajorDeltaCompactionOp(d64237f60ebb455a95f33ecd6fbaa867): perf score=1.000000
I20260812 06:18:58.209870  6757 maintenance_manager.cc:643] P 0089bb36467f40ebac4b5b3a3418382f: MajorDeltaCompactionOp(d64237f60ebb455a95f33ecd6fbaa867) complete. Timing: real 0.152s	user 0.112s	sys 0.040s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733833,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":890,"lbm_read_time_us":10375,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29539,"lbm_writes_lt_1ms":543,"mutex_wait_us":348,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2048,"update_count":2500}
I20260812 06:18:58.210642  6826 maintenance_manager.cc:419] P 0089bb36467f40ebac4b5b3a3418382f: Scheduling FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867): perf score=11.118625
I20260812 06:18:58.282450  6757 maintenance_manager.cc:643] P 0089bb36467f40ebac4b5b3a3418382f: FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867) complete. Timing: real 0.072s	user 0.028s	sys 0.012s Metrics: {"bytes_written":12840810,"delete_count":0,"lbm_write_time_us":38682,"lbm_writes_1-10_ms":2,"lbm_writes_10-100_ms":1,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1565}
I20260812 06:18:58.283070  6826 maintenance_manager.cc:419] P 0089bb36467f40ebac4b5b3a3418382f: Scheduling FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867): perf score=6.157687
I20260812 06:18:58.307564  6757 maintenance_manager.cc:643] P 0089bb36467f40ebac4b5b3a3418382f: FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867) complete. Timing: real 0.024s	user 0.015s	sys 0.007s Metrics: {"bytes_written":7671765,"delete_count":0,"lbm_write_time_us":10311,"lbm_writes_lt_1ms":190,"reinsert_count":0,"update_count":935}
I20260812 06:18:58.308305  6826 maintenance_manager.cc:419] P 0089bb36467f40ebac4b5b3a3418382f: Scheduling MajorDeltaCompactionOp(d64237f60ebb455a95f33ecd6fbaa867): perf score=1.000000
I20260812 06:18:58.498788  6757 maintenance_manager.cc:643] P 0089bb36467f40ebac4b5b3a3418382f: MajorDeltaCompactionOp(d64237f60ebb455a95f33ecd6fbaa867) complete. Timing: real 0.190s	user 0.146s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733732,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":306,"lbm_read_time_us":12881,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33451,"lbm_writes_lt_1ms":543,"mutex_wait_us":46,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":2500}
I20260812 06:18:58.499400  6826 maintenance_manager.cc:419] P 0089bb36467f40ebac4b5b3a3418382f: Scheduling FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867): perf score=14.095187
I20260812 06:18:58.562451  6757 maintenance_manager.cc:643] P 0089bb36467f40ebac4b5b3a3418382f: FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867) complete. Timing: real 0.063s	user 0.038s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24284,"lbm_writes_lt_1ms":403,"mutex_wait_us":49,"reinsert_count":0,"update_count":2000}
I20260812 06:18:58.563045  6826 maintenance_manager.cc:419] P 0089bb36467f40ebac4b5b3a3418382f: Scheduling FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867): perf score=2.188937
I20260812 06:18:58.575121  6757 maintenance_manager.cc:643] P 0089bb36467f40ebac4b5b3a3418382f: FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4514,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:58.576020  6826 maintenance_manager.cc:419] P 0089bb36467f40ebac4b5b3a3418382f: Scheduling MajorDeltaCompactionOp(d64237f60ebb455a95f33ecd6fbaa867): perf score=1.000000
I20260812 06:18:58.761739  6757 maintenance_manager.cc:643] P 0089bb36467f40ebac4b5b3a3418382f: MajorDeltaCompactionOp(d64237f60ebb455a95f33ecd6fbaa867) complete. Timing: real 0.185s	user 0.129s	sys 0.056s 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":180,"lbm_read_time_us":12926,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31630,"lbm_writes_lt_1ms":543,"mutex_wait_us":64,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11904,"update_count":2500}
I20260812 06:18:58.762550  6826 maintenance_manager.cc:419] P 0089bb36467f40ebac4b5b3a3418382f: Scheduling FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867): perf score=14.095187
I20260812 06:18:58.823599  6757 maintenance_manager.cc:643] P 0089bb36467f40ebac4b5b3a3418382f: FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867) complete. Timing: real 0.061s	user 0.036s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23838,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:58.824250  6826 maintenance_manager.cc:419] P 0089bb36467f40ebac4b5b3a3418382f: Scheduling FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867): perf score=2.188937
I20260812 06:18:58.838193  6757 maintenance_manager.cc:643] P 0089bb36467f40ebac4b5b3a3418382f: FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867) complete. Timing: real 0.014s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5376,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:58.838792  6826 maintenance_manager.cc:419] P 0089bb36467f40ebac4b5b3a3418382f: Scheduling FlushMRSOp(d64237f60ebb455a95f33ecd6fbaa867): perf score=1.000000
I20260812 06:18:58.876330  6757 maintenance_manager.cc:643] P 0089bb36467f40ebac4b5b3a3418382f: FlushMRSOp(d64237f60ebb455a95f33ecd6fbaa867) complete. Timing: real 0.037s	user 0.031s	sys 0.005s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":61,"dirs.run_cpu_time_us":206,"dirs.run_wall_time_us":1570,"drs_written":1,"lbm_read_time_us":41,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1804,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:18:58.877102  6826 maintenance_manager.cc:419] P 0089bb36467f40ebac4b5b3a3418382f: Scheduling LogGCOp(d64237f60ebb455a95f33ecd6fbaa867): free 133024394 bytes of WAL
I20260812 06:18:58.877341  6757 log_reader.cc:385] T d64237f60ebb455a95f33ecd6fbaa867: removed 13 log segments from log reader
I20260812 06:18:58.877404  6757 log.cc:1079] T d64237f60ebb455a95f33ecd6fbaa867 P 0089bb36467f40ebac4b5b3a3418382f: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/d64237f60ebb455a95f33ecd6fbaa867/wal-000000015 (ops 70-74)
I20260812 06:18:58.877458  6757 log.cc:1079] T d64237f60ebb455a95f33ecd6fbaa867 P 0089bb36467f40ebac4b5b3a3418382f: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/d64237f60ebb455a95f33ecd6fbaa867/wal-000000016 (ops 75-78)
I20260812 06:18:58.877516  6757 log.cc:1079] T d64237f60ebb455a95f33ecd6fbaa867 P 0089bb36467f40ebac4b5b3a3418382f: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/d64237f60ebb455a95f33ecd6fbaa867/wal-000000017 (ops 79-83)
I20260812 06:18:58.877556  6757 log.cc:1079] T d64237f60ebb455a95f33ecd6fbaa867 P 0089bb36467f40ebac4b5b3a3418382f: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/d64237f60ebb455a95f33ecd6fbaa867/wal-000000018 (ops 84-88)
I20260812 06:18:58.877610  6757 log.cc:1079] T d64237f60ebb455a95f33ecd6fbaa867 P 0089bb36467f40ebac4b5b3a3418382f: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/d64237f60ebb455a95f33ecd6fbaa867/wal-000000019 (ops 89-93)
I20260812 06:18:58.877735  6757 log.cc:1079] T d64237f60ebb455a95f33ecd6fbaa867 P 0089bb36467f40ebac4b5b3a3418382f: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/d64237f60ebb455a95f33ecd6fbaa867/wal-000000020 (ops 94-98)
I20260812 06:18:58.877780  6757 log.cc:1079] T d64237f60ebb455a95f33ecd6fbaa867 P 0089bb36467f40ebac4b5b3a3418382f: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/d64237f60ebb455a95f33ecd6fbaa867/wal-000000021 (ops 99-103)
I20260812 06:18:58.877817  6757 log.cc:1079] T d64237f60ebb455a95f33ecd6fbaa867 P 0089bb36467f40ebac4b5b3a3418382f: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/d64237f60ebb455a95f33ecd6fbaa867/wal-000000022 (ops 104-108)
I20260812 06:18:58.877856  6757 log.cc:1079] T d64237f60ebb455a95f33ecd6fbaa867 P 0089bb36467f40ebac4b5b3a3418382f: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/d64237f60ebb455a95f33ecd6fbaa867/wal-000000023 (ops 109-113)
I20260812 06:18:58.877892  6757 log.cc:1079] T d64237f60ebb455a95f33ecd6fbaa867 P 0089bb36467f40ebac4b5b3a3418382f: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/d64237f60ebb455a95f33ecd6fbaa867/wal-000000024 (ops 114-118)
I20260812 06:18:58.877928  6757 log.cc:1079] T d64237f60ebb455a95f33ecd6fbaa867 P 0089bb36467f40ebac4b5b3a3418382f: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/d64237f60ebb455a95f33ecd6fbaa867/wal-000000025 (ops 119-123)
I20260812 06:18:58.877965  6757 log.cc:1079] T d64237f60ebb455a95f33ecd6fbaa867 P 0089bb36467f40ebac4b5b3a3418382f: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/d64237f60ebb455a95f33ecd6fbaa867/wal-000000026 (ops 124-128)
I20260812 06:18:58.878001  6757 log.cc:1079] T d64237f60ebb455a95f33ecd6fbaa867 P 0089bb36467f40ebac4b5b3a3418382f: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/d64237f60ebb455a95f33ecd6fbaa867/wal-000000027 (ops 129-133)
I20260812 06:18:58.908663  6757 maintenance_manager.cc:643] P 0089bb36467f40ebac4b5b3a3418382f: LogGCOp(d64237f60ebb455a95f33ecd6fbaa867) complete. Timing: real 0.031s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:18:58.909282  6826 maintenance_manager.cc:419] P 0089bb36467f40ebac4b5b3a3418382f: Scheduling UndoDeltaBlockGCOp(d64237f60ebb455a95f33ecd6fbaa867): 495 bytes on disk
I20260812 06:18:58.909752  6757 maintenance_manager.cc:643] P 0089bb36467f40ebac4b5b3a3418382f: UndoDeltaBlockGCOp(d64237f60ebb455a95f33ecd6fbaa867) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4}
I20260812 06:18:58.910671  6826 maintenance_manager.cc:419] P 0089bb36467f40ebac4b5b3a3418382f: Scheduling FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867): perf score=4.173312
I20260812 06:18:58.930023  6757 maintenance_manager.cc:643] P 0089bb36467f40ebac4b5b3a3418382f: FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867) complete. Timing: real 0.019s	user 0.005s	sys 0.012s Metrics: {"bytes_written":5374417,"delete_count":0,"lbm_write_time_us":8323,"lbm_writes_lt_1ms":134,"reinsert_count":0,"update_count":655}
I20260812 06:18:58.930636  6826 maintenance_manager.cc:419] P 0089bb36467f40ebac4b5b3a3418382f: Scheduling FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867): perf score=1.196750
I20260812 06:18:58.940165  6757 maintenance_manager.cc:643] P 0089bb36467f40ebac4b5b3a3418382f: FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867) complete. Timing: real 0.009s	user 0.007s	sys 0.001s Metrics: {"bytes_written":2830880,"delete_count":0,"lbm_write_time_us":3035,"lbm_writes_lt_1ms":72,"reinsert_count":0,"update_count":345}
I20260812 06:18:58.940729  6826 maintenance_manager.cc:419] P 0089bb36467f40ebac4b5b3a3418382f: Scheduling MajorDeltaCompactionOp(d64237f60ebb455a95f33ecd6fbaa867): perf score=1.000000
I20260812 06:18:59.170284  6757 maintenance_manager.cc:643] P 0089bb36467f40ebac4b5b3a3418382f: MajorDeltaCompactionOp(d64237f60ebb455a95f33ecd6fbaa867) complete. Timing: real 0.229s	user 0.152s	sys 0.072s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32938758,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":3229,"lbm_read_time_us":16575,"lbm_reads_lt_1ms":774,"lbm_write_time_us":39937,"lbm_writes_lt_1ms":743,"mutex_wait_us":2283,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":3072,"thread_start_us":98,"threads_started":1,"update_count":3500}
I20260812 06:18:59.171068  6826 maintenance_manager.cc:419] P 0089bb36467f40ebac4b5b3a3418382f: Scheduling FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867): perf score=18.063937
I20260812 06:18:59.230019  6757 maintenance_manager.cc:643] P 0089bb36467f40ebac4b5b3a3418382f: FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867) complete. Timing: real 0.059s	user 0.030s	sys 0.023s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":25816,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:59.230613  6826 maintenance_manager.cc:419] P 0089bb36467f40ebac4b5b3a3418382f: Scheduling FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867): perf score=2.188937
I20260812 06:18:59.242736  6757 maintenance_manager.cc:643] P 0089bb36467f40ebac4b5b3a3418382f: FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4407,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:59.243221  6826 maintenance_manager.cc:419] P 0089bb36467f40ebac4b5b3a3418382f: Scheduling MajorDeltaCompactionOp(d64237f60ebb455a95f33ecd6fbaa867): perf score=1.000000
I20260812 06:18:59.412631  6757 maintenance_manager.cc:643] P 0089bb36467f40ebac4b5b3a3418382f: MajorDeltaCompactionOp(d64237f60ebb455a95f33ecd6fbaa867) complete. Timing: real 0.169s	user 0.128s	sys 0.040s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28836137,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":453,"lbm_read_time_us":13731,"lbm_reads_lt_1ms":672,"lbm_write_time_us":32940,"lbm_writes_lt_1ms":643,"mutex_wait_us":40,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":14848,"update_count":3000}
I20260812 06:18:59.413120  6826 maintenance_manager.cc:419] P 0089bb36467f40ebac4b5b3a3418382f: Scheduling FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867): perf score=14.095187
I20260812 06:18:59.470209  6757 maintenance_manager.cc:643] P 0089bb36467f40ebac4b5b3a3418382f: FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867) complete. Timing: real 0.057s	user 0.032s	sys 0.011s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":20356,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:59.470903  6826 maintenance_manager.cc:419] P 0089bb36467f40ebac4b5b3a3418382f: Scheduling FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867): perf score=2.188937
I20260812 06:18:59.483976  6757 maintenance_manager.cc:643] P 0089bb36467f40ebac4b5b3a3418382f: FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4693,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:59.484514  6826 maintenance_manager.cc:419] P 0089bb36467f40ebac4b5b3a3418382f: Scheduling MajorDeltaCompactionOp(d64237f60ebb455a95f33ecd6fbaa867): perf score=1.000000
I20260812 06:18:59.652359  6757 maintenance_manager.cc:643] P 0089bb36467f40ebac4b5b3a3418382f: MajorDeltaCompactionOp(d64237f60ebb455a95f33ecd6fbaa867) complete. Timing: real 0.168s	user 0.132s	sys 0.035s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733722,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":298,"lbm_read_time_us":11688,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30742,"lbm_writes_lt_1ms":543,"mutex_wait_us":24,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12288,"update_count":2500}
I20260812 06:18:59.653297  6826 maintenance_manager.cc:419] P 0089bb36467f40ebac4b5b3a3418382f: Scheduling FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867): perf score=14.095187
I20260812 06:18:59.701949  6757 maintenance_manager.cc:643] P 0089bb36467f40ebac4b5b3a3418382f: FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867) complete. Timing: real 0.048s	user 0.020s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21376,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:59.702678  6826 maintenance_manager.cc:419] P 0089bb36467f40ebac4b5b3a3418382f: Scheduling MajorDeltaCompactionOp(d64237f60ebb455a95f33ecd6fbaa867): perf score=1.000000
I20260812 06:18:59.851456  6757 maintenance_manager.cc:643] P 0089bb36467f40ebac4b5b3a3418382f: MajorDeltaCompactionOp(d64237f60ebb455a95f33ecd6fbaa867) complete. Timing: real 0.149s	user 0.094s	sys 0.049s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20631192,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":981,"lbm_read_time_us":10271,"lbm_reads_lt_1ms":463,"lbm_write_time_us":23293,"lbm_writes_lt_1ms":443,"mutex_wait_us":279,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":17408,"update_count":2000}
I20260812 06:18:59.851951  6826 maintenance_manager.cc:419] P 0089bb36467f40ebac4b5b3a3418382f: Scheduling FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867): perf score=14.095187
I20260812 06:18:59.907706  6757 maintenance_manager.cc:643] P 0089bb36467f40ebac4b5b3a3418382f: FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867) complete. Timing: real 0.056s	user 0.034s	sys 0.011s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20704,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:59.908325  6826 maintenance_manager.cc:419] P 0089bb36467f40ebac4b5b3a3418382f: Scheduling FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867): perf score=2.188937
I20260812 06:18:59.921279  6757 maintenance_manager.cc:643] P 0089bb36467f40ebac4b5b3a3418382f: FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4742,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:59.921876  6826 maintenance_manager.cc:419] P 0089bb36467f40ebac4b5b3a3418382f: Scheduling MajorDeltaCompactionOp(d64237f60ebb455a95f33ecd6fbaa867): perf score=1.000000
I20260812 06:19:00.110175  6757 maintenance_manager.cc:643] P 0089bb36467f40ebac4b5b3a3418382f: MajorDeltaCompactionOp(d64237f60ebb455a95f33ecd6fbaa867) complete. Timing: real 0.188s	user 0.122s	sys 0.059s 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":687,"lbm_read_time_us":10090,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29424,"lbm_writes_lt_1ms":543,"mutex_wait_us":37,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10496,"update_count":2500}
I20260812 06:19:00.114476  6826 maintenance_manager.cc:419] P 0089bb36467f40ebac4b5b3a3418382f: Scheduling FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867): perf score=14.095187
I20260812 06:19:00.162142  6757 maintenance_manager.cc:643] P 0089bb36467f40ebac4b5b3a3418382f: FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867) complete. Timing: real 0.047s	user 0.037s	sys 0.007s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20915,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:00.162729  6826 maintenance_manager.cc:419] P 0089bb36467f40ebac4b5b3a3418382f: Scheduling FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867): perf score=2.188937
I20260812 06:19:00.175130  6757 maintenance_manager.cc:643] P 0089bb36467f40ebac4b5b3a3418382f: FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4507,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:00.175668  6826 maintenance_manager.cc:419] P 0089bb36467f40ebac4b5b3a3418382f: Scheduling MajorDeltaCompactionOp(d64237f60ebb455a95f33ecd6fbaa867): perf score=1.000000
I20260812 06:19:00.334156  6757 maintenance_manager.cc:643] P 0089bb36467f40ebac4b5b3a3418382f: MajorDeltaCompactionOp(d64237f60ebb455a95f33ecd6fbaa867) complete. Timing: real 0.158s	user 0.093s	sys 0.059s 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":1659,"lbm_read_time_us":9933,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29698,"lbm_writes_lt_1ms":543,"mutex_wait_us":502,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2500}
I20260812 06:19:00.335035  6826 maintenance_manager.cc:419] P 0089bb36467f40ebac4b5b3a3418382f: Scheduling FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867): perf score=11.118625
I20260812 06:19:00.377182  6757 maintenance_manager.cc:643] P 0089bb36467f40ebac4b5b3a3418382f: FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867) complete. Timing: real 0.042s	user 0.015s	sys 0.024s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":18058,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:19:00.377758  6826 maintenance_manager.cc:419] P 0089bb36467f40ebac4b5b3a3418382f: Scheduling FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867): perf score=2.188937
I20260812 06:19:00.390703  6757 maintenance_manager.cc:643] P 0089bb36467f40ebac4b5b3a3418382f: FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867) complete. Timing: real 0.013s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4030,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:00.391167  6826 maintenance_manager.cc:419] P 0089bb36467f40ebac4b5b3a3418382f: Scheduling FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867): perf score=2.188937
I20260812 06:19:00.400516  6757 maintenance_manager.cc:643] P 0089bb36467f40ebac4b5b3a3418382f: FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867) complete. Timing: real 0.009s	user 0.005s	sys 0.002s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3532,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:00.401017  6826 maintenance_manager.cc:419] P 0089bb36467f40ebac4b5b3a3418382f: Scheduling FlushMRSOp(d64237f60ebb455a95f33ecd6fbaa867): perf score=1.000000
I20260812 06:19:00.436223  6757 maintenance_manager.cc:643] P 0089bb36467f40ebac4b5b3a3418382f: FlushMRSOp(d64237f60ebb455a95f33ecd6fbaa867) complete. Timing: real 0.035s	user 0.030s	sys 0.003s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":63,"dirs.run_cpu_time_us":212,"dirs.run_wall_time_us":1600,"drs_written":1,"lbm_read_time_us":98,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1744,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:19:00.436939  6826 maintenance_manager.cc:419] P 0089bb36467f40ebac4b5b3a3418382f: Scheduling LogGCOp(d64237f60ebb455a95f33ecd6fbaa867): free 129320789 bytes of WAL
I20260812 06:19:00.437171  6757 log_reader.cc:385] T d64237f60ebb455a95f33ecd6fbaa867: removed 13 log segments from log reader
I20260812 06:19:00.437229  6757 log.cc:1079] T d64237f60ebb455a95f33ecd6fbaa867 P 0089bb36467f40ebac4b5b3a3418382f: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/d64237f60ebb455a95f33ecd6fbaa867/wal-000000028 (ops 134-138)
I20260812 06:19:00.437281  6757 log.cc:1079] T d64237f60ebb455a95f33ecd6fbaa867 P 0089bb36467f40ebac4b5b3a3418382f: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/d64237f60ebb455a95f33ecd6fbaa867/wal-000000029 (ops 139-143)
I20260812 06:19:00.437345  6757 log.cc:1079] T d64237f60ebb455a95f33ecd6fbaa867 P 0089bb36467f40ebac4b5b3a3418382f: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/d64237f60ebb455a95f33ecd6fbaa867/wal-000000030 (ops 144-148)
I20260812 06:19:00.437386  6757 log.cc:1079] T d64237f60ebb455a95f33ecd6fbaa867 P 0089bb36467f40ebac4b5b3a3418382f: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/d64237f60ebb455a95f33ecd6fbaa867/wal-000000031 (ops 149-152)
I20260812 06:19:00.437422  6757 log.cc:1079] T d64237f60ebb455a95f33ecd6fbaa867 P 0089bb36467f40ebac4b5b3a3418382f: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/d64237f60ebb455a95f33ecd6fbaa867/wal-000000032 (ops 153-157)
I20260812 06:19:00.437458  6757 log.cc:1079] T d64237f60ebb455a95f33ecd6fbaa867 P 0089bb36467f40ebac4b5b3a3418382f: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/d64237f60ebb455a95f33ecd6fbaa867/wal-000000033 (ops 158-162)
I20260812 06:19:00.437495  6757 log.cc:1079] T d64237f60ebb455a95f33ecd6fbaa867 P 0089bb36467f40ebac4b5b3a3418382f: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/d64237f60ebb455a95f33ecd6fbaa867/wal-000000034 (ops 163-167)
I20260812 06:19:00.437531  6757 log.cc:1079] T d64237f60ebb455a95f33ecd6fbaa867 P 0089bb36467f40ebac4b5b3a3418382f: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/d64237f60ebb455a95f33ecd6fbaa867/wal-000000035 (ops 168-172)
I20260812 06:19:00.437567  6757 log.cc:1079] T d64237f60ebb455a95f33ecd6fbaa867 P 0089bb36467f40ebac4b5b3a3418382f: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/d64237f60ebb455a95f33ecd6fbaa867/wal-000000036 (ops 173-177)
I20260812 06:19:00.437603  6757 log.cc:1079] T d64237f60ebb455a95f33ecd6fbaa867 P 0089bb36467f40ebac4b5b3a3418382f: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/d64237f60ebb455a95f33ecd6fbaa867/wal-000000037 (ops 178-182)
I20260812 06:19:00.437641  6757 log.cc:1079] T d64237f60ebb455a95f33ecd6fbaa867 P 0089bb36467f40ebac4b5b3a3418382f: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/d64237f60ebb455a95f33ecd6fbaa867/wal-000000038 (ops 183-186)
I20260812 06:19:00.437678  6757 log.cc:1079] T d64237f60ebb455a95f33ecd6fbaa867 P 0089bb36467f40ebac4b5b3a3418382f: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/d64237f60ebb455a95f33ecd6fbaa867/wal-000000039 (ops 187-191)
I20260812 06:19:00.437713  6757 log.cc:1079] T d64237f60ebb455a95f33ecd6fbaa867 P 0089bb36467f40ebac4b5b3a3418382f: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/d64237f60ebb455a95f33ecd6fbaa867/wal-000000040 (ops 192-196)
I20260812 06:19:00.466454  6757 maintenance_manager.cc:643] P 0089bb36467f40ebac4b5b3a3418382f: LogGCOp(d64237f60ebb455a95f33ecd6fbaa867) complete. Timing: real 0.029s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:19:00.466862  6826 maintenance_manager.cc:419] P 0089bb36467f40ebac4b5b3a3418382f: Scheduling FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867): perf score=4.173312
I20260812 06:19:00.473083  6648 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.880s	user 1.842s	sys 0.151s
I20260812 06:19:00.481024  6757 maintenance_manager.cc:643] P 0089bb36467f40ebac4b5b3a3418382f: FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867) complete. Timing: real 0.014s	user 0.007s	sys 0.006s Metrics: {"bytes_written":5743633,"delete_count":0,"lbm_write_time_us":6167,"lbm_writes_lt_1ms":143,"reinsert_count":0,"update_count":700}
I20260812 06:19:00.481491  6826 maintenance_manager.cc:419] P 0089bb36467f40ebac4b5b3a3418382f: Scheduling FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867): perf score=1.196750
I20260812 06:19:00.488526  6757 maintenance_manager.cc:643] P 0089bb36467f40ebac4b5b3a3418382f: FlushDeltaMemStoresOp(d64237f60ebb455a95f33ecd6fbaa867) complete. Timing: real 0.007s	user 0.006s	sys 0.000s Metrics: {"bytes_written":2461654,"delete_count":0,"lbm_write_time_us":2625,"lbm_writes_lt_1ms":63,"reinsert_count":0,"update_count":300}
I20260812 06:19:00.489046  6826 maintenance_manager.cc:419] P 0089bb36467f40ebac4b5b3a3418382f: Scheduling MajorDeltaCompactionOp(d64237f60ebb455a95f33ecd6fbaa867): perf score=1.000000
I20260812 06:19:00.540616  6648 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.067s	user 0.002s	sys 0.000s
I20260812 06:19:00.541392  6648 tablet_server.cc:179] TabletServer@127.6.126.1:0 shutting down...
I20260812 06:19:00.636767  6757 maintenance_manager.cc:643] P 0089bb36467f40ebac4b5b3a3418382f: MajorDeltaCompactionOp(d64237f60ebb455a95f33ecd6fbaa867) complete. Timing: real 0.148s	user 0.118s	sys 0.029s Metrics: {"cfile_cache_hit":391,"cfile_cache_hit_bytes":15919176,"cfile_cache_miss":344,"cfile_cache_miss_bytes":17019682,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":752,"lbm_read_time_us":6470,"lbm_reads_lt_1ms":380,"lbm_write_time_us":34064,"lbm_writes_lt_1ms":743,"mutex_wait_us":23,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":15872,"thread_start_us":89,"threads_started":1,"update_count":3500}
I20260812 06:19:00.637692  6648 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:00.638229  6648 tablet_replica.cc:333] T d64237f60ebb455a95f33ecd6fbaa867 P 0089bb36467f40ebac4b5b3a3418382f: stopping tablet replica
I20260812 06:19:00.638512  6648 raft_consensus.cc:2243] T d64237f60ebb455a95f33ecd6fbaa867 P 0089bb36467f40ebac4b5b3a3418382f [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:00.638768  6648 raft_consensus.cc:2272] T d64237f60ebb455a95f33ecd6fbaa867 P 0089bb36467f40ebac4b5b3a3418382f [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:00.654667  6648 tablet_server.cc:196] TabletServer@127.6.126.1:0 shutdown complete.
I20260812 06:19:00.695654  6648 master.cc:562] Master@127.6.126.62:40035 shutting down...
I20260812 06:19:00.700094  6648 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 8f5c30d957bd40ce89f374e9b40c7eb2 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:00.700307  6648 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 8f5c30d957bd40ce89f374e9b40c7eb2 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:00.700404  6648 tablet_replica.cc:333] T 00000000000000000000000000000000 P 8f5c30d957bd40ce89f374e9b40c7eb2: stopping tablet replica
I20260812 06:19:00.712981  6648 master.cc:584] Master@127.6.126.62:40035 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5494 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:19:00.812933  6648 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.6.126.62:46815
I20260812 06:19:00.813383  6648 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:00.815598  6860 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:19:00.815675  6863 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:19:00.815687  6861 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:19:00.815784  6648 server_base.cc:1061] running on GCE node
I20260812 06:19:00.816027  6648 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:00.816067  6648 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:19:00.816083  6648 hybrid_clock.cc:648] HybridClock initialized: now 1786515540816083 us; error 0 us; skew 500 ppm
I20260812 06:19:00.817049  6648 webserver.cc:533] Webserver started at http://127.6.126.62:46749/ using document root <none> and password file <none>
I20260812 06:19:00.817243  6648 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:00.817324  6648 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:00.817410  6648 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:00.817819  6648 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535294106-6648-0/minicluster-data/master-0-root/instance:
uuid: "a266515a6697491bb01b976f04b5e5db"
format_stamp: "Formatted at 2026-08-12 06:19:00 on dist-test-slave-zpfg"
I20260812 06:19:00.819422  6648 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:19:00.820379  6869 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:19:00.820645  6648 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:00.820710  6648 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535294106-6648-0/minicluster-data/master-0-root
uuid: "a266515a6697491bb01b976f04b5e5db"
format_stamp: "Formatted at 2026-08-12 06:19:00 on dist-test-slave-zpfg"
I20260812 06:19:00.820768  6648 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535294106-6648-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535294106-6648-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535294106-6648-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:19:00.825965  6648 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:00.826277  6648 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:00.830260  6648 rpc_server.cc:307] RPC server started. Bound to: 127.6.126.62:46815
I20260812 06:19:00.833732  6925 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.6.126.62:46815 every 8 connection(s)
I20260812 06:19:00.834211  6926 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:19:00.836158  6926 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a266515a6697491bb01b976f04b5e5db: Bootstrap starting.
I20260812 06:19:00.836982  6926 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P a266515a6697491bb01b976f04b5e5db: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:00.838086  6926 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a266515a6697491bb01b976f04b5e5db: No bootstrap required, opened a new log
I20260812 06:19:00.838589  6926 raft_consensus.cc:359] T 00000000000000000000000000000000 P a266515a6697491bb01b976f04b5e5db [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a266515a6697491bb01b976f04b5e5db" member_type: VOTER }
I20260812 06:19:00.838680  6926 raft_consensus.cc:385] T 00000000000000000000000000000000 P a266515a6697491bb01b976f04b5e5db [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:00.838702  6926 raft_consensus.cc:740] T 00000000000000000000000000000000 P a266515a6697491bb01b976f04b5e5db [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: a266515a6697491bb01b976f04b5e5db, State: Initialized, Role: FOLLOWER
I20260812 06:19:00.838944  6926 consensus_queue.cc:260] T 00000000000000000000000000000000 P a266515a6697491bb01b976f04b5e5db [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: "a266515a6697491bb01b976f04b5e5db" member_type: VOTER }
I20260812 06:19:00.839041  6926 raft_consensus.cc:399] T 00000000000000000000000000000000 P a266515a6697491bb01b976f04b5e5db [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:00.839107  6926 raft_consensus.cc:493] T 00000000000000000000000000000000 P a266515a6697491bb01b976f04b5e5db [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:00.839170  6926 raft_consensus.cc:3060] T 00000000000000000000000000000000 P a266515a6697491bb01b976f04b5e5db [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:00.839913  6926 raft_consensus.cc:515] T 00000000000000000000000000000000 P a266515a6697491bb01b976f04b5e5db [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a266515a6697491bb01b976f04b5e5db" member_type: VOTER }
I20260812 06:19:00.840065  6926 leader_election.cc:304] T 00000000000000000000000000000000 P a266515a6697491bb01b976f04b5e5db [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: a266515a6697491bb01b976f04b5e5db; no voters: 
I20260812 06:19:00.840283  6926 leader_election.cc:290] T 00000000000000000000000000000000 P a266515a6697491bb01b976f04b5e5db [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:00.840422  6929 raft_consensus.cc:2804] T 00000000000000000000000000000000 P a266515a6697491bb01b976f04b5e5db [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:00.840667  6929 raft_consensus.cc:697] T 00000000000000000000000000000000 P a266515a6697491bb01b976f04b5e5db [term 1 LEADER]: Becoming Leader. State: Replica: a266515a6697491bb01b976f04b5e5db, State: Running, Role: LEADER
I20260812 06:19:00.840816  6929 consensus_queue.cc:237] T 00000000000000000000000000000000 P a266515a6697491bb01b976f04b5e5db [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: "a266515a6697491bb01b976f04b5e5db" member_type: VOTER }
I20260812 06:19:00.840845  6926 sys_catalog.cc:565] T 00000000000000000000000000000000 P a266515a6697491bb01b976f04b5e5db [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:00.841300  6930 sys_catalog.cc:455] T 00000000000000000000000000000000 P a266515a6697491bb01b976f04b5e5db [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "a266515a6697491bb01b976f04b5e5db" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a266515a6697491bb01b976f04b5e5db" member_type: VOTER } }
I20260812 06:19:00.841423  6930 sys_catalog.cc:458] T 00000000000000000000000000000000 P a266515a6697491bb01b976f04b5e5db [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:00.841312  6931 sys_catalog.cc:455] T 00000000000000000000000000000000 P a266515a6697491bb01b976f04b5e5db [sys.catalog]: SysCatalogTable state changed. Reason: New leader a266515a6697491bb01b976f04b5e5db. Latest consensus state: current_term: 1 leader_uuid: "a266515a6697491bb01b976f04b5e5db" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a266515a6697491bb01b976f04b5e5db" member_type: VOTER } }
I20260812 06:19:00.841560  6931 sys_catalog.cc:458] T 00000000000000000000000000000000 P a266515a6697491bb01b976f04b5e5db [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:00.841995  6934 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:00.842762  6934 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:00.842935  6648 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:00.844682  6934 catalog_manager.cc:1383] Generated new cluster ID: 697e2490f9aa4b548340972348af5c0a
I20260812 06:19:00.844749  6934 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:00.860129  6934 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:00.860777  6934 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:00.872689  6934 catalog_manager.cc:6092] T 00000000000000000000000000000000 P a266515a6697491bb01b976f04b5e5db: Generated new TSK 0
I20260812 06:19:00.872884  6934 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:00.875411  6648 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:00.877576  6952 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:19:00.877609  6949 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:19:00.877576  6950 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:19:00.877827  6648 server_base.cc:1061] running on GCE node
I20260812 06:19:00.878181  6648 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:00.878227  6648 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:19:00.878243  6648 hybrid_clock.cc:648] HybridClock initialized: now 1786515540878243 us; error 0 us; skew 500 ppm
I20260812 06:19:00.879123  6648 webserver.cc:533] Webserver started at http://127.6.126.1:42661/ using document root <none> and password file <none>
I20260812 06:19:00.879269  6648 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:00.879316  6648 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:00.879395  6648 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:00.879756  6648 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535294106-6648-0/minicluster-data/ts-0-root/instance:
uuid: "9cd7d9fd563942a0baaa0700ffb28827"
format_stamp: "Formatted at 2026-08-12 06:19:00 on dist-test-slave-zpfg"
I20260812 06:19:00.881232  6648 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:00.882149  6958 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:19:00.882450  6648 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:00.882519  6648 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535294106-6648-0/minicluster-data/ts-0-root
uuid: "9cd7d9fd563942a0baaa0700ffb28827"
format_stamp: "Formatted at 2026-08-12 06:19:00 on dist-test-slave-zpfg"
I20260812 06:19:00.882613  6648 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535294106-6648-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535294106-6648-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535294106-6648-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:19:00.887253  6648 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:00.887640  6648 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:00.887952  6648 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:00.888444  6648 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:00.888506  6648 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:00.888571  6648 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:00.888623  6648 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:00.893003  6648 rpc_server.cc:307] RPC server started. Bound to: 127.6.126.1:46383
I20260812 06:19:00.894456  7027 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.6.126.1:46383 every 8 connection(s)
I20260812 06:19:00.903577  7028 heartbeater.cc:344] Connected to a master server at 127.6.126.62:46815
I20260812 06:19:00.903723  7028 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:00.904052  7028 heartbeater.cc:507] Master 127.6.126.62:46815 requested a full tablet report, sending...
I20260812 06:19:00.904748  6888 ts_manager.cc:194] Registered new tserver with Master: 9cd7d9fd563942a0baaa0700ffb28827 (127.6.126.1:46383)
I20260812 06:19:00.905040  6648 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011031734s
I20260812 06:19:00.905679  6888 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:57162
I20260812 06:19:00.912778  6888 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:57166:
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:19:00.922228  6988 tablet_service.cc:1511] Processing CreateTablet for tablet e39dc3c86bf446a3864f1a0dcea43b78 (DEFAULT_TABLE table=heavy-update-compaction-test [id=b592c527eb344ef6b70e0a19c08614bb]), partition=
I20260812 06:19:00.922712  6988 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet e39dc3c86bf446a3864f1a0dcea43b78. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:00.925555  7041 tablet_bootstrap.cc:492] T e39dc3c86bf446a3864f1a0dcea43b78 P 9cd7d9fd563942a0baaa0700ffb28827: Bootstrap starting.
I20260812 06:19:00.926620  7041 tablet_bootstrap.cc:654] T e39dc3c86bf446a3864f1a0dcea43b78 P 9cd7d9fd563942a0baaa0700ffb28827: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:00.927912  7041 tablet_bootstrap.cc:492] T e39dc3c86bf446a3864f1a0dcea43b78 P 9cd7d9fd563942a0baaa0700ffb28827: No bootstrap required, opened a new log
I20260812 06:19:00.928067  7041 ts_tablet_manager.cc:1403] T e39dc3c86bf446a3864f1a0dcea43b78 P 9cd7d9fd563942a0baaa0700ffb28827: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:19:00.928678  7041 raft_consensus.cc:359] T e39dc3c86bf446a3864f1a0dcea43b78 P 9cd7d9fd563942a0baaa0700ffb28827 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9cd7d9fd563942a0baaa0700ffb28827" member_type: VOTER last_known_addr { host: "127.6.126.1" port: 46383 } }
I20260812 06:19:00.928817  7041 raft_consensus.cc:385] T e39dc3c86bf446a3864f1a0dcea43b78 P 9cd7d9fd563942a0baaa0700ffb28827 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:00.928893  7041 raft_consensus.cc:740] T e39dc3c86bf446a3864f1a0dcea43b78 P 9cd7d9fd563942a0baaa0700ffb28827 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 9cd7d9fd563942a0baaa0700ffb28827, State: Initialized, Role: FOLLOWER
I20260812 06:19:00.929088  7041 consensus_queue.cc:260] T e39dc3c86bf446a3864f1a0dcea43b78 P 9cd7d9fd563942a0baaa0700ffb28827 [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: "9cd7d9fd563942a0baaa0700ffb28827" member_type: VOTER last_known_addr { host: "127.6.126.1" port: 46383 } }
I20260812 06:19:00.929207  7041 raft_consensus.cc:399] T e39dc3c86bf446a3864f1a0dcea43b78 P 9cd7d9fd563942a0baaa0700ffb28827 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:00.929257  7041 raft_consensus.cc:493] T e39dc3c86bf446a3864f1a0dcea43b78 P 9cd7d9fd563942a0baaa0700ffb28827 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:00.929317  7041 raft_consensus.cc:3060] T e39dc3c86bf446a3864f1a0dcea43b78 P 9cd7d9fd563942a0baaa0700ffb28827 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:00.930160  7041 raft_consensus.cc:515] T e39dc3c86bf446a3864f1a0dcea43b78 P 9cd7d9fd563942a0baaa0700ffb28827 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9cd7d9fd563942a0baaa0700ffb28827" member_type: VOTER last_known_addr { host: "127.6.126.1" port: 46383 } }
I20260812 06:19:00.930409  7041 leader_election.cc:304] T e39dc3c86bf446a3864f1a0dcea43b78 P 9cd7d9fd563942a0baaa0700ffb28827 [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: 9cd7d9fd563942a0baaa0700ffb28827; no voters: 
I20260812 06:19:00.930687  7041 leader_election.cc:290] T e39dc3c86bf446a3864f1a0dcea43b78 P 9cd7d9fd563942a0baaa0700ffb28827 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:00.930825  7043 raft_consensus.cc:2804] T e39dc3c86bf446a3864f1a0dcea43b78 P 9cd7d9fd563942a0baaa0700ffb28827 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:00.931102  7043 raft_consensus.cc:697] T e39dc3c86bf446a3864f1a0dcea43b78 P 9cd7d9fd563942a0baaa0700ffb28827 [term 1 LEADER]: Becoming Leader. State: Replica: 9cd7d9fd563942a0baaa0700ffb28827, State: Running, Role: LEADER
I20260812 06:19:00.931176  7028 heartbeater.cc:499] Master 127.6.126.62:46815 was elected leader, sending a full tablet report...
I20260812 06:19:00.931288  7043 consensus_queue.cc:237] T e39dc3c86bf446a3864f1a0dcea43b78 P 9cd7d9fd563942a0baaa0700ffb28827 [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: "9cd7d9fd563942a0baaa0700ffb28827" member_type: VOTER last_known_addr { host: "127.6.126.1" port: 46383 } }
I20260812 06:19:00.931108  7041 ts_tablet_manager.cc:1434] T e39dc3c86bf446a3864f1a0dcea43b78 P 9cd7d9fd563942a0baaa0700ffb28827: Time spent starting tablet: real 0.003s	user 0.001s	sys 0.003s
I20260812 06:19:00.932902  6888 catalog_manager.cc:5719] T e39dc3c86bf446a3864f1a0dcea43b78 P 9cd7d9fd563942a0baaa0700ffb28827 reported cstate change: term changed from 0 to 1, leader changed from <none> to 9cd7d9fd563942a0baaa0700ffb28827 (127.6.126.1). New cstate: current_term: 1 leader_uuid: "9cd7d9fd563942a0baaa0700ffb28827" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9cd7d9fd563942a0baaa0700ffb28827" member_type: VOTER last_known_addr { host: "127.6.126.1" port: 46383 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:00.992985  6648 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.054s	user 0.015s	sys 0.009s
I20260812 06:19:01.145066  7029 maintenance_manager.cc:419] P 9cd7d9fd563942a0baaa0700ffb28827: Scheduling FlushMRSOp(e39dc3c86bf446a3864f1a0dcea43b78): perf score=19.054940
I20260812 06:19:01.305197  6963 maintenance_manager.cc:643] P 9cd7d9fd563942a0baaa0700ffb28827: FlushMRSOp(e39dc3c86bf446a3864f1a0dcea43b78) complete. Timing: real 0.160s	user 0.106s	sys 0.051s Metrics: {"bytes_written":12307491,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":94,"dirs.run_cpu_time_us":176,"dirs.run_wall_time_us":930,"drs_written":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4,"lbm_write_time_us":39208,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:19:01.305948  7029 maintenance_manager.cc:419] P 9cd7d9fd563942a0baaa0700ffb28827: Scheduling LogGCOp(e39dc3c86bf446a3864f1a0dcea43b78): free 20743831 bytes of WAL
I20260812 06:19:01.306241  6963 log_reader.cc:385] T e39dc3c86bf446a3864f1a0dcea43b78: removed 2 log segments from log reader
I20260812 06:19:01.306285  6963 log.cc:1079] T e39dc3c86bf446a3864f1a0dcea43b78 P 9cd7d9fd563942a0baaa0700ffb28827: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/e39dc3c86bf446a3864f1a0dcea43b78/wal-000000001 (ops 1-6)
I20260812 06:19:01.306317  6963 log.cc:1079] T e39dc3c86bf446a3864f1a0dcea43b78 P 9cd7d9fd563942a0baaa0700ffb28827: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/e39dc3c86bf446a3864f1a0dcea43b78/wal-000000002 (ops 7-11)
I20260812 06:19:01.310717  6963 maintenance_manager.cc:643] P 9cd7d9fd563942a0baaa0700ffb28827: LogGCOp(e39dc3c86bf446a3864f1a0dcea43b78) complete. Timing: real 0.005s	user 0.001s	sys 0.003s Metrics: {}
I20260812 06:19:01.311143  7029 maintenance_manager.cc:419] P 9cd7d9fd563942a0baaa0700ffb28827: Scheduling FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78): perf score=2.188937
I20260812 06:19:01.323040  6963 maintenance_manager.cc:643] P 9cd7d9fd563942a0baaa0700ffb28827: FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78) complete. Timing: real 0.012s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4548,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:01.323705  7029 maintenance_manager.cc:419] P 9cd7d9fd563942a0baaa0700ffb28827: Scheduling UndoDeltaBlockGCOp(e39dc3c86bf446a3864f1a0dcea43b78): 16411396 bytes on disk
I20260812 06:19:01.324347  6963 maintenance_manager.cc:643] P 9cd7d9fd563942a0baaa0700ffb28827: UndoDeltaBlockGCOp(e39dc3c86bf446a3864f1a0dcea43b78) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":111,"lbm_reads_lt_1ms":4}
I20260812 06:19:01.324921  7029 maintenance_manager.cc:419] P 9cd7d9fd563942a0baaa0700ffb28827: Scheduling MajorDeltaCompactionOp(e39dc3c86bf446a3864f1a0dcea43b78): perf score=1.000000
I20260812 06:19:01.486931  6963 maintenance_manager.cc:643] P 9cd7d9fd563942a0baaa0700ffb28827: MajorDeltaCompactionOp(e39dc3c86bf446a3864f1a0dcea43b78) complete. Timing: real 0.162s	user 0.107s	sys 0.055s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":972,"lbm_read_time_us":12623,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24355,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8320,"thread_start_us":507,"threads_started":5,"update_count":2000}
I20260812 06:19:01.487639  7029 maintenance_manager.cc:419] P 9cd7d9fd563942a0baaa0700ffb28827: Scheduling FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78): perf score=10.126437
I20260812 06:19:01.526393  6963 maintenance_manager.cc:643] P 9cd7d9fd563942a0baaa0700ffb28827: FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78) complete. Timing: real 0.039s	user 0.027s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16588,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:01.527009  7029 maintenance_manager.cc:419] P 9cd7d9fd563942a0baaa0700ffb28827: Scheduling FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78): perf score=2.188937
I20260812 06:19:01.541365  6963 maintenance_manager.cc:643] P 9cd7d9fd563942a0baaa0700ffb28827: FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78) complete. Timing: real 0.014s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5055,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:01.541882  7029 maintenance_manager.cc:419] P 9cd7d9fd563942a0baaa0700ffb28827: Scheduling MajorDeltaCompactionOp(e39dc3c86bf446a3864f1a0dcea43b78): perf score=1.000000
I20260812 06:19:01.670892  6963 maintenance_manager.cc:643] P 9cd7d9fd563942a0baaa0700ffb28827: MajorDeltaCompactionOp(e39dc3c86bf446a3864f1a0dcea43b78) complete. Timing: real 0.129s	user 0.109s	sys 0.019s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":155,"lbm_read_time_us":9626,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22357,"lbm_writes_lt_1ms":443,"mutex_wait_us":32,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":40576,"update_count":2000}
I20260812 06:19:01.671734  7029 maintenance_manager.cc:419] P 9cd7d9fd563942a0baaa0700ffb28827: Scheduling FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78): perf score=10.126437
I20260812 06:19:01.705404  6963 maintenance_manager.cc:643] P 9cd7d9fd563942a0baaa0700ffb28827: FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78) complete. Timing: real 0.033s	user 0.023s	sys 0.007s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":14575,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:01.705924  7029 maintenance_manager.cc:419] P 9cd7d9fd563942a0baaa0700ffb28827: Scheduling FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78): perf score=2.188937
I20260812 06:19:01.717087  6963 maintenance_manager.cc:643] P 9cd7d9fd563942a0baaa0700ffb28827: FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4362,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:01.717581  7029 maintenance_manager.cc:419] P 9cd7d9fd563942a0baaa0700ffb28827: Scheduling MajorDeltaCompactionOp(e39dc3c86bf446a3864f1a0dcea43b78): perf score=1.000000
I20260812 06:19:01.847946  6963 maintenance_manager.cc:643] P 9cd7d9fd563942a0baaa0700ffb28827: MajorDeltaCompactionOp(e39dc3c86bf446a3864f1a0dcea43b78) complete. Timing: real 0.130s	user 0.117s	sys 0.013s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672275,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":172,"lbm_read_time_us":8319,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24673,"lbm_writes_lt_1ms":443,"mutex_wait_us":45,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4736,"update_count":2000}
I20260812 06:19:01.848632  7029 maintenance_manager.cc:419] P 9cd7d9fd563942a0baaa0700ffb28827: Scheduling FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78): perf score=10.126437
I20260812 06:19:01.882922  6963 maintenance_manager.cc:643] P 9cd7d9fd563942a0baaa0700ffb28827: FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78) complete. Timing: real 0.034s	user 0.019s	sys 0.012s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14466,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:01.883555  7029 maintenance_manager.cc:419] P 9cd7d9fd563942a0baaa0700ffb28827: Scheduling MajorDeltaCompactionOp(e39dc3c86bf446a3864f1a0dcea43b78): perf score=1.000000
I20260812 06:19:02.012809  6963 maintenance_manager.cc:643] P 9cd7d9fd563942a0baaa0700ffb28827: MajorDeltaCompactionOp(e39dc3c86bf446a3864f1a0dcea43b78) complete. Timing: real 0.129s	user 0.086s	sys 0.043s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569747,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":837,"lbm_read_time_us":9544,"lbm_reads_lt_1ms":367,"lbm_write_time_us":19404,"lbm_writes_lt_1ms":343,"mutex_wait_us":98,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":15616,"update_count":1500}
I20260812 06:19:02.013532  7029 maintenance_manager.cc:419] P 9cd7d9fd563942a0baaa0700ffb28827: Scheduling FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78): perf score=10.126437
I20260812 06:19:02.073515  6963 maintenance_manager.cc:643] P 9cd7d9fd563942a0baaa0700ffb28827: FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78) complete. Timing: real 0.060s	user 0.029s	sys 0.020s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":24908,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:19:02.074103  7029 maintenance_manager.cc:419] P 9cd7d9fd563942a0baaa0700ffb28827: Scheduling FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78): perf score=2.188937
I20260812 06:19:02.086848  6963 maintenance_manager.cc:643] P 9cd7d9fd563942a0baaa0700ffb28827: FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78) complete. Timing: real 0.013s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4446,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:02.087496  7029 maintenance_manager.cc:419] P 9cd7d9fd563942a0baaa0700ffb28827: Scheduling MajorDeltaCompactionOp(e39dc3c86bf446a3864f1a0dcea43b78): perf score=1.000000
I20260812 06:19:02.238628  6963 maintenance_manager.cc:643] P 9cd7d9fd563942a0baaa0700ffb28827: MajorDeltaCompactionOp(e39dc3c86bf446a3864f1a0dcea43b78) complete. Timing: real 0.151s	user 0.110s	sys 0.039s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672280,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":2413,"lbm_read_time_us":10402,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27245,"lbm_writes_lt_1ms":443,"mutex_wait_us":1959,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13696,"update_count":2000}
I20260812 06:19:02.239524  7029 maintenance_manager.cc:419] P 9cd7d9fd563942a0baaa0700ffb28827: Scheduling FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78): perf score=10.126437
I20260812 06:19:02.287140  6963 maintenance_manager.cc:643] P 9cd7d9fd563942a0baaa0700ffb28827: FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78) complete. Timing: real 0.047s	user 0.022s	sys 0.024s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":19516,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:02.287940  7029 maintenance_manager.cc:419] P 9cd7d9fd563942a0baaa0700ffb28827: Scheduling FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78): perf score=2.188937
I20260812 06:19:02.314553  6963 maintenance_manager.cc:643] P 9cd7d9fd563942a0baaa0700ffb28827: FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78) complete. Timing: real 0.026s	user 0.000s	sys 0.015s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5286,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:02.315189  7029 maintenance_manager.cc:419] P 9cd7d9fd563942a0baaa0700ffb28827: Scheduling FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78): perf score=2.188937
I20260812 06:19:02.329977  6963 maintenance_manager.cc:643] P 9cd7d9fd563942a0baaa0700ffb28827: FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5046,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:02.330615  7029 maintenance_manager.cc:419] P 9cd7d9fd563942a0baaa0700ffb28827: Scheduling MajorDeltaCompactionOp(e39dc3c86bf446a3864f1a0dcea43b78): perf score=1.000000
I20260812 06:19:02.494731  6963 maintenance_manager.cc:643] P 9cd7d9fd563942a0baaa0700ffb28827: MajorDeltaCompactionOp(e39dc3c86bf446a3864f1a0dcea43b78) complete. Timing: real 0.164s	user 0.116s	sys 0.045s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774806,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":105,"lbm_read_time_us":12340,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30483,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":73088,"update_count":2500}
I20260812 06:19:02.495473  7029 maintenance_manager.cc:419] P 9cd7d9fd563942a0baaa0700ffb28827: Scheduling FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78): perf score=14.095187
I20260812 06:19:02.545152  6963 maintenance_manager.cc:643] P 9cd7d9fd563942a0baaa0700ffb28827: FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78) complete. Timing: real 0.050s	user 0.023s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23320,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:19:02.545698  7029 maintenance_manager.cc:419] P 9cd7d9fd563942a0baaa0700ffb28827: Scheduling FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78): perf score=2.188937
I20260812 06:19:02.560559  6963 maintenance_manager.cc:643] P 9cd7d9fd563942a0baaa0700ffb28827: FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5526,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:02.561167  7029 maintenance_manager.cc:419] P 9cd7d9fd563942a0baaa0700ffb28827: Scheduling FlushMRSOp(e39dc3c86bf446a3864f1a0dcea43b78): perf score=1.000000
I20260812 06:19:02.587728  6963 maintenance_manager.cc:643] P 9cd7d9fd563942a0baaa0700ffb28827: FlushMRSOp(e39dc3c86bf446a3864f1a0dcea43b78) complete. Timing: real 0.026s	user 0.021s	sys 0.004s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":66,"dirs.run_cpu_time_us":250,"dirs.run_wall_time_us":1621,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1412,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:02.588433  7029 maintenance_manager.cc:419] P 9cd7d9fd563942a0baaa0700ffb28827: Scheduling LogGCOp(e39dc3c86bf446a3864f1a0dcea43b78): free 112239308 bytes of WAL
I20260812 06:19:02.588811  6963 log_reader.cc:385] T e39dc3c86bf446a3864f1a0dcea43b78: removed 11 log segments from log reader
I20260812 06:19:02.588917  6963 log.cc:1079] T e39dc3c86bf446a3864f1a0dcea43b78 P 9cd7d9fd563942a0baaa0700ffb28827: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/e39dc3c86bf446a3864f1a0dcea43b78/wal-000000003 (ops 12-16)
I20260812 06:19:02.588999  6963 log.cc:1079] T e39dc3c86bf446a3864f1a0dcea43b78 P 9cd7d9fd563942a0baaa0700ffb28827: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/e39dc3c86bf446a3864f1a0dcea43b78/wal-000000004 (ops 17-21)
I20260812 06:19:02.589076  6963 log.cc:1079] T e39dc3c86bf446a3864f1a0dcea43b78 P 9cd7d9fd563942a0baaa0700ffb28827: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/e39dc3c86bf446a3864f1a0dcea43b78/wal-000000005 (ops 22-26)
I20260812 06:19:02.589143  6963 log.cc:1079] T e39dc3c86bf446a3864f1a0dcea43b78 P 9cd7d9fd563942a0baaa0700ffb28827: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/e39dc3c86bf446a3864f1a0dcea43b78/wal-000000006 (ops 27-31)
I20260812 06:19:02.589206  6963 log.cc:1079] T e39dc3c86bf446a3864f1a0dcea43b78 P 9cd7d9fd563942a0baaa0700ffb28827: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/e39dc3c86bf446a3864f1a0dcea43b78/wal-000000007 (ops 32-36)
I20260812 06:19:02.589277  6963 log.cc:1079] T e39dc3c86bf446a3864f1a0dcea43b78 P 9cd7d9fd563942a0baaa0700ffb28827: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/e39dc3c86bf446a3864f1a0dcea43b78/wal-000000008 (ops 37-40)
I20260812 06:19:02.589347  6963 log.cc:1079] T e39dc3c86bf446a3864f1a0dcea43b78 P 9cd7d9fd563942a0baaa0700ffb28827: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/e39dc3c86bf446a3864f1a0dcea43b78/wal-000000009 (ops 41-45)
I20260812 06:19:02.589408  6963 log.cc:1079] T e39dc3c86bf446a3864f1a0dcea43b78 P 9cd7d9fd563942a0baaa0700ffb28827: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/e39dc3c86bf446a3864f1a0dcea43b78/wal-000000010 (ops 46-50)
I20260812 06:19:02.589483  6963 log.cc:1079] T e39dc3c86bf446a3864f1a0dcea43b78 P 9cd7d9fd563942a0baaa0700ffb28827: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/e39dc3c86bf446a3864f1a0dcea43b78/wal-000000011 (ops 51-55)
I20260812 06:19:02.589555  6963 log.cc:1079] T e39dc3c86bf446a3864f1a0dcea43b78 P 9cd7d9fd563942a0baaa0700ffb28827: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/e39dc3c86bf446a3864f1a0dcea43b78/wal-000000012 (ops 56-60)
I20260812 06:19:02.589622  6963 log.cc:1079] T e39dc3c86bf446a3864f1a0dcea43b78 P 9cd7d9fd563942a0baaa0700ffb28827: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/e39dc3c86bf446a3864f1a0dcea43b78/wal-000000013 (ops 61-65)
I20260812 06:19:02.614295  6963 maintenance_manager.cc:643] P 9cd7d9fd563942a0baaa0700ffb28827: LogGCOp(e39dc3c86bf446a3864f1a0dcea43b78) complete. Timing: real 0.026s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:19:02.615011  7029 maintenance_manager.cc:419] P 9cd7d9fd563942a0baaa0700ffb28827: Scheduling UndoDeltaBlockGCOp(e39dc3c86bf446a3864f1a0dcea43b78): 472 bytes on disk
I20260812 06:19:02.615520  6963 maintenance_manager.cc:643] P 9cd7d9fd563942a0baaa0700ffb28827: UndoDeltaBlockGCOp(e39dc3c86bf446a3864f1a0dcea43b78) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4}
I20260812 06:19:02.616026  7029 maintenance_manager.cc:419] P 9cd7d9fd563942a0baaa0700ffb28827: Scheduling FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78): perf score=4.173312
I20260812 06:19:02.635448  6963 maintenance_manager.cc:643] P 9cd7d9fd563942a0baaa0700ffb28827: FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78) complete. Timing: real 0.019s	user 0.010s	sys 0.008s Metrics: {"bytes_written":6194894,"delete_count":0,"lbm_write_time_us":8237,"lbm_writes_lt_1ms":154,"reinsert_count":0,"update_count":755}
I20260812 06:19:02.635965  7029 maintenance_manager.cc:419] P 9cd7d9fd563942a0baaa0700ffb28827: Scheduling LogGCOp(e39dc3c86bf446a3864f1a0dcea43b78): free 8767174 bytes of WAL
I20260812 06:19:02.636227  6963 log_reader.cc:385] T e39dc3c86bf446a3864f1a0dcea43b78: removed 1 log segments from log reader
I20260812 06:19:02.636292  6963 log.cc:1079] T e39dc3c86bf446a3864f1a0dcea43b78 P 9cd7d9fd563942a0baaa0700ffb28827: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/e39dc3c86bf446a3864f1a0dcea43b78/wal-000000014 (ops 66-70)
I20260812 06:19:02.638517  6963 maintenance_manager.cc:643] P 9cd7d9fd563942a0baaa0700ffb28827: LogGCOp(e39dc3c86bf446a3864f1a0dcea43b78) complete. Timing: real 0.002s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:19:02.638839  7029 maintenance_manager.cc:419] P 9cd7d9fd563942a0baaa0700ffb28827: Scheduling FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78): perf score=1.000000
I20260812 06:19:02.649370  6963 maintenance_manager.cc:643] P 9cd7d9fd563942a0baaa0700ffb28827: FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78) complete. Timing: real 0.010s	user 0.008s	sys 0.001s Metrics: {"bytes_written":2010377,"delete_count":0,"lbm_write_time_us":3479,"lbm_writes_lt_1ms":52,"reinsert_count":0,"update_count":245}
I20260812 06:19:02.649888  7029 maintenance_manager.cc:419] P 9cd7d9fd563942a0baaa0700ffb28827: Scheduling MajorDeltaCompactionOp(e39dc3c86bf446a3864f1a0dcea43b78): perf score=1.000000
I20260812 06:19:02.853034  6963 maintenance_manager.cc:643] P 9cd7d9fd563942a0baaa0700ffb28827: MajorDeltaCompactionOp(e39dc3c86bf446a3864f1a0dcea43b78) complete. Timing: real 0.203s	user 0.155s	sys 0.047s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979697,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":784,"lbm_read_time_us":14625,"lbm_reads_lt_1ms":774,"lbm_write_time_us":40845,"lbm_writes_lt_1ms":743,"mutex_wait_us":285,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":16128,"thread_start_us":82,"threads_started":1,"update_count":3500}
I20260812 06:19:02.853858  7029 maintenance_manager.cc:419] P 9cd7d9fd563942a0baaa0700ffb28827: Scheduling FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78): perf score=15.087375
I20260812 06:19:02.904806  6963 maintenance_manager.cc:643] P 9cd7d9fd563942a0baaa0700ffb28827: FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78) complete. Timing: real 0.051s	user 0.048s	sys 0.000s Metrics: {"bytes_written":16738096,"delete_count":0,"lbm_write_time_us":21967,"lbm_writes_lt_1ms":411,"reinsert_count":0,"update_count":2040}
I20260812 06:19:02.905416  7029 maintenance_manager.cc:419] P 9cd7d9fd563942a0baaa0700ffb28827: Scheduling FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78): perf score=2.188937
I20260812 06:19:02.922330  6963 maintenance_manager.cc:643] P 9cd7d9fd563942a0baaa0700ffb28827: FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78) complete. Timing: real 0.017s	user 0.010s	sys 0.003s Metrics: {"bytes_written":3774459,"delete_count":0,"lbm_write_time_us":6063,"lbm_writes_lt_1ms":95,"reinsert_count":0,"update_count":460}
I20260812 06:19:02.922956  7029 maintenance_manager.cc:419] P 9cd7d9fd563942a0baaa0700ffb28827: Scheduling MajorDeltaCompactionOp(e39dc3c86bf446a3864f1a0dcea43b78): perf score=1.000000
I20260812 06:19:03.079213  6963 maintenance_manager.cc:643] P 9cd7d9fd563942a0baaa0700ffb28827: MajorDeltaCompactionOp(e39dc3c86bf446a3864f1a0dcea43b78) complete. Timing: real 0.156s	user 0.131s	sys 0.018s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774683,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":218,"lbm_read_time_us":10481,"lbm_reads_lt_1ms":564,"lbm_write_time_us":28333,"lbm_writes_lt_1ms":543,"mutex_wait_us":57,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11776,"update_count":2500}
I20260812 06:19:03.082515  7029 maintenance_manager.cc:419] P 9cd7d9fd563942a0baaa0700ffb28827: Scheduling FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78): perf score=14.095187
I20260812 06:19:03.141242  6963 maintenance_manager.cc:643] P 9cd7d9fd563942a0baaa0700ffb28827: FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78) complete. Timing: real 0.058s	user 0.030s	sys 0.020s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":23426,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:03.141788  7029 maintenance_manager.cc:419] P 9cd7d9fd563942a0baaa0700ffb28827: Scheduling FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78): perf score=2.188937
I20260812 06:19:03.152966  6963 maintenance_manager.cc:643] P 9cd7d9fd563942a0baaa0700ffb28827: FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3932,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:03.153599  7029 maintenance_manager.cc:419] P 9cd7d9fd563942a0baaa0700ffb28827: Scheduling MajorDeltaCompactionOp(e39dc3c86bf446a3864f1a0dcea43b78): perf score=1.000000
I20260812 06:19:03.333061  6963 maintenance_manager.cc:643] P 9cd7d9fd563942a0baaa0700ffb28827: MajorDeltaCompactionOp(e39dc3c86bf446a3864f1a0dcea43b78) complete. Timing: real 0.179s	user 0.129s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":397,"lbm_read_time_us":10407,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29702,"lbm_writes_lt_1ms":543,"mutex_wait_us":50,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":51328,"update_count":2500}
I20260812 06:19:03.333721  7029 maintenance_manager.cc:419] P 9cd7d9fd563942a0baaa0700ffb28827: Scheduling FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78): perf score=14.095187
I20260812 06:19:03.390807  6963 maintenance_manager.cc:643] P 9cd7d9fd563942a0baaa0700ffb28827: FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78) complete. Timing: real 0.057s	user 0.033s	sys 0.023s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":25766,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:03.391320  7029 maintenance_manager.cc:419] P 9cd7d9fd563942a0baaa0700ffb28827: Scheduling MajorDeltaCompactionOp(e39dc3c86bf446a3864f1a0dcea43b78): perf score=1.000000
I20260812 06:19:03.551563  6963 maintenance_manager.cc:643] P 9cd7d9fd563942a0baaa0700ffb28827: MajorDeltaCompactionOp(e39dc3c86bf446a3864f1a0dcea43b78) complete. Timing: real 0.160s	user 0.096s	sys 0.052s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672158,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":313,"lbm_read_time_us":11370,"lbm_reads_lt_1ms":467,"lbm_write_time_us":24853,"lbm_writes_lt_1ms":443,"mutex_wait_us":24,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":21888,"update_count":2000}
I20260812 06:19:03.552192  7029 maintenance_manager.cc:419] P 9cd7d9fd563942a0baaa0700ffb28827: Scheduling FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78): perf score=14.095187
I20260812 06:19:03.606105  6963 maintenance_manager.cc:643] P 9cd7d9fd563942a0baaa0700ffb28827: FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78) complete. Timing: real 0.054s	user 0.021s	sys 0.028s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23250,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:03.606711  7029 maintenance_manager.cc:419] P 9cd7d9fd563942a0baaa0700ffb28827: Scheduling FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78): perf score=2.188937
I20260812 06:19:03.620591  6963 maintenance_manager.cc:643] P 9cd7d9fd563942a0baaa0700ffb28827: FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4729,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:03.621176  7029 maintenance_manager.cc:419] P 9cd7d9fd563942a0baaa0700ffb28827: Scheduling MajorDeltaCompactionOp(e39dc3c86bf446a3864f1a0dcea43b78): perf score=1.000000
I20260812 06:19:03.811033  6963 maintenance_manager.cc:643] P 9cd7d9fd563942a0baaa0700ffb28827: MajorDeltaCompactionOp(e39dc3c86bf446a3864f1a0dcea43b78) complete. Timing: real 0.190s	user 0.137s	sys 0.051s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1061,"lbm_read_time_us":12348,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29365,"lbm_writes_lt_1ms":543,"mutex_wait_us":330,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:03.811729  7029 maintenance_manager.cc:419] P 9cd7d9fd563942a0baaa0700ffb28827: Scheduling FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78): perf score=14.095187
I20260812 06:19:03.861670  6963 maintenance_manager.cc:643] P 9cd7d9fd563942a0baaa0700ffb28827: FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78) complete. Timing: real 0.050s	user 0.027s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20577,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:03.862192  7029 maintenance_manager.cc:419] P 9cd7d9fd563942a0baaa0700ffb28827: Scheduling FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78): perf score=2.188937
I20260812 06:19:03.874424  6963 maintenance_manager.cc:643] P 9cd7d9fd563942a0baaa0700ffb28827: FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78) complete. Timing: real 0.012s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4192,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:03.875015  7029 maintenance_manager.cc:419] P 9cd7d9fd563942a0baaa0700ffb28827: Scheduling MajorDeltaCompactionOp(e39dc3c86bf446a3864f1a0dcea43b78): perf score=1.000000
I20260812 06:19:04.040915  6963 maintenance_manager.cc:643] P 9cd7d9fd563942a0baaa0700ffb28827: MajorDeltaCompactionOp(e39dc3c86bf446a3864f1a0dcea43b78) complete. Timing: real 0.166s	user 0.119s	sys 0.032s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":363,"lbm_read_time_us":9334,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30125,"lbm_writes_lt_1ms":543,"mutex_wait_us":3,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6272,"update_count":2500}
I20260812 06:19:04.041610  7029 maintenance_manager.cc:419] P 9cd7d9fd563942a0baaa0700ffb28827: Scheduling FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78): perf score=14.095187
I20260812 06:19:04.098044  6963 maintenance_manager.cc:643] P 9cd7d9fd563942a0baaa0700ffb28827: FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78) complete. Timing: real 0.056s	user 0.028s	sys 0.016s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":21452,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:04.098661  7029 maintenance_manager.cc:419] P 9cd7d9fd563942a0baaa0700ffb28827: Scheduling FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78): perf score=2.188937
I20260812 06:19:04.110846  6963 maintenance_manager.cc:643] P 9cd7d9fd563942a0baaa0700ffb28827: FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4517,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:04.111346  7029 maintenance_manager.cc:419] P 9cd7d9fd563942a0baaa0700ffb28827: Scheduling FlushMRSOp(e39dc3c86bf446a3864f1a0dcea43b78): perf score=1.000000
I20260812 06:19:04.140209  6963 maintenance_manager.cc:643] P 9cd7d9fd563942a0baaa0700ffb28827: FlushMRSOp(e39dc3c86bf446a3864f1a0dcea43b78) complete. Timing: real 0.029s	user 0.026s	sys 0.001s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":69,"dirs.run_cpu_time_us":243,"dirs.run_wall_time_us":1673,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1776,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:04.140921  7029 maintenance_manager.cc:419] P 9cd7d9fd563942a0baaa0700ffb28827: Scheduling LogGCOp(e39dc3c86bf446a3864f1a0dcea43b78): free 123804205 bytes of WAL
I20260812 06:19:04.141152  6963 log_reader.cc:385] T e39dc3c86bf446a3864f1a0dcea43b78: removed 12 log segments from log reader
I20260812 06:19:04.141212  6963 log.cc:1079] T e39dc3c86bf446a3864f1a0dcea43b78 P 9cd7d9fd563942a0baaa0700ffb28827: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/e39dc3c86bf446a3864f1a0dcea43b78/wal-000000015 (ops 71-74)
I20260812 06:19:04.141268  6963 log.cc:1079] T e39dc3c86bf446a3864f1a0dcea43b78 P 9cd7d9fd563942a0baaa0700ffb28827: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/e39dc3c86bf446a3864f1a0dcea43b78/wal-000000016 (ops 75-79)
I20260812 06:19:04.141304  6963 log.cc:1079] T e39dc3c86bf446a3864f1a0dcea43b78 P 9cd7d9fd563942a0baaa0700ffb28827: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/e39dc3c86bf446a3864f1a0dcea43b78/wal-000000017 (ops 80-84)
I20260812 06:19:04.141361  6963 log.cc:1079] T e39dc3c86bf446a3864f1a0dcea43b78 P 9cd7d9fd563942a0baaa0700ffb28827: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/e39dc3c86bf446a3864f1a0dcea43b78/wal-000000018 (ops 85-89)
I20260812 06:19:04.141431  6963 log.cc:1079] T e39dc3c86bf446a3864f1a0dcea43b78 P 9cd7d9fd563942a0baaa0700ffb28827: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/e39dc3c86bf446a3864f1a0dcea43b78/wal-000000019 (ops 90-94)
I20260812 06:19:04.141475  6963 log.cc:1079] T e39dc3c86bf446a3864f1a0dcea43b78 P 9cd7d9fd563942a0baaa0700ffb28827: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/e39dc3c86bf446a3864f1a0dcea43b78/wal-000000020 (ops 95-99)
I20260812 06:19:04.141520  6963 log.cc:1079] T e39dc3c86bf446a3864f1a0dcea43b78 P 9cd7d9fd563942a0baaa0700ffb28827: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/e39dc3c86bf446a3864f1a0dcea43b78/wal-000000021 (ops 100-104)
I20260812 06:19:04.141559  6963 log.cc:1079] T e39dc3c86bf446a3864f1a0dcea43b78 P 9cd7d9fd563942a0baaa0700ffb28827: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/e39dc3c86bf446a3864f1a0dcea43b78/wal-000000022 (ops 105-108)
I20260812 06:19:04.141603  6963 log.cc:1079] T e39dc3c86bf446a3864f1a0dcea43b78 P 9cd7d9fd563942a0baaa0700ffb28827: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/e39dc3c86bf446a3864f1a0dcea43b78/wal-000000023 (ops 109-113)
I20260812 06:19:04.141639  6963 log.cc:1079] T e39dc3c86bf446a3864f1a0dcea43b78 P 9cd7d9fd563942a0baaa0700ffb28827: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/e39dc3c86bf446a3864f1a0dcea43b78/wal-000000024 (ops 114-118)
I20260812 06:19:04.141686  6963 log.cc:1079] T e39dc3c86bf446a3864f1a0dcea43b78 P 9cd7d9fd563942a0baaa0700ffb28827: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/e39dc3c86bf446a3864f1a0dcea43b78/wal-000000025 (ops 119-123)
I20260812 06:19:04.141724  6963 log.cc:1079] T e39dc3c86bf446a3864f1a0dcea43b78 P 9cd7d9fd563942a0baaa0700ffb28827: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/e39dc3c86bf446a3864f1a0dcea43b78/wal-000000026 (ops 124-128)
I20260812 06:19:04.168294  6963 maintenance_manager.cc:643] P 9cd7d9fd563942a0baaa0700ffb28827: LogGCOp(e39dc3c86bf446a3864f1a0dcea43b78) complete. Timing: real 0.027s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:19:04.168735  7029 maintenance_manager.cc:419] P 9cd7d9fd563942a0baaa0700ffb28827: Scheduling FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78): perf score=3.181125
I20260812 06:19:04.195050  6963 maintenance_manager.cc:643] P 9cd7d9fd563942a0baaa0700ffb28827: FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78) complete. Timing: real 0.026s	user 0.006s	sys 0.020s Metrics: {"bytes_written":4676999,"delete_count":0,"lbm_write_time_us":5482,"lbm_writes_lt_1ms":117,"reinsert_count":0,"update_count":570}
I20260812 06:19:04.195739  7029 maintenance_manager.cc:419] P 9cd7d9fd563942a0baaa0700ffb28827: Scheduling UndoDeltaBlockGCOp(e39dc3c86bf446a3864f1a0dcea43b78): 473 bytes on disk
I20260812 06:19:04.196256  6963 maintenance_manager.cc:643] P 9cd7d9fd563942a0baaa0700ffb28827: UndoDeltaBlockGCOp(e39dc3c86bf446a3864f1a0dcea43b78) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":65,"lbm_reads_lt_1ms":4}
I20260812 06:19:04.196774  7029 maintenance_manager.cc:419] P 9cd7d9fd563942a0baaa0700ffb28827: Scheduling FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78): perf score=2.188937
I20260812 06:19:04.206763  6963 maintenance_manager.cc:643] P 9cd7d9fd563942a0baaa0700ffb28827: FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3528305,"delete_count":0,"lbm_write_time_us":3832,"lbm_writes_lt_1ms":89,"reinsert_count":0,"update_count":430}
I20260812 06:19:04.207302  7029 maintenance_manager.cc:419] P 9cd7d9fd563942a0baaa0700ffb28827: Scheduling MajorDeltaCompactionOp(e39dc3c86bf446a3864f1a0dcea43b78): perf score=1.000000
I20260812 06:19:04.485044  6963 maintenance_manager.cc:643] P 9cd7d9fd563942a0baaa0700ffb28827: MajorDeltaCompactionOp(e39dc3c86bf446a3864f1a0dcea43b78) complete. Timing: real 0.278s	user 0.146s	sys 0.120s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979735,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":782,"lbm_read_time_us":17309,"lbm_reads_lt_1ms":774,"lbm_write_time_us":44672,"lbm_writes_lt_1ms":743,"mutex_wait_us":92,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":7552,"thread_start_us":85,"threads_started":1,"update_count":3500}
I20260812 06:19:04.485844  7029 maintenance_manager.cc:419] P 9cd7d9fd563942a0baaa0700ffb28827: Scheduling FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78): perf score=18.063937
I20260812 06:19:04.557542  6963 maintenance_manager.cc:643] P 9cd7d9fd563942a0baaa0700ffb28827: FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78) complete. Timing: real 0.071s	user 0.047s	sys 0.005s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":25438,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:04.558043  7029 maintenance_manager.cc:419] P 9cd7d9fd563942a0baaa0700ffb28827: Scheduling FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78): perf score=2.188937
I20260812 06:19:04.568670  6963 maintenance_manager.cc:643] P 9cd7d9fd563942a0baaa0700ffb28827: FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3833,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:04.569557  7029 maintenance_manager.cc:419] P 9cd7d9fd563942a0baaa0700ffb28827: Scheduling MajorDeltaCompactionOp(e39dc3c86bf446a3864f1a0dcea43b78): perf score=1.000000
I20260812 06:19:04.792395  6963 maintenance_manager.cc:643] P 9cd7d9fd563942a0baaa0700ffb28827: MajorDeltaCompactionOp(e39dc3c86bf446a3864f1a0dcea43b78) complete. Timing: real 0.223s	user 0.140s	sys 0.076s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877102,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":316,"lbm_read_time_us":14282,"lbm_reads_lt_1ms":672,"lbm_write_time_us":36820,"lbm_writes_lt_1ms":643,"mutex_wait_us":44,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":3000}
I20260812 06:19:04.793512  7029 maintenance_manager.cc:419] P 9cd7d9fd563942a0baaa0700ffb28827: Scheduling FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78): perf score=16.079562
I20260812 06:19:04.836750  6963 maintenance_manager.cc:643] P 9cd7d9fd563942a0baaa0700ffb28827: FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78) complete. Timing: real 0.043s	user 0.029s	sys 0.012s Metrics: {"bytes_written":17640627,"delete_count":0,"lbm_write_time_us":19291,"lbm_writes_lt_1ms":433,"reinsert_count":0,"update_count":2150}
I20260812 06:19:04.837380  7029 maintenance_manager.cc:419] P 9cd7d9fd563942a0baaa0700ffb28827: Scheduling FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78): perf score=2.188937
I20260812 06:19:04.862186  6963 maintenance_manager.cc:643] P 9cd7d9fd563942a0baaa0700ffb28827: FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78) complete. Timing: real 0.025s	user 0.000s	sys 0.011s Metrics: {"bytes_written":3282159,"delete_count":0,"lbm_write_time_us":5006,"lbm_writes_lt_1ms":83,"reinsert_count":0,"update_count":400}
I20260812 06:19:04.862756  7029 maintenance_manager.cc:419] P 9cd7d9fd563942a0baaa0700ffb28827: Scheduling FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78): perf score=2.188937
I20260812 06:19:04.872531  6963 maintenance_manager.cc:643] P 9cd7d9fd563942a0baaa0700ffb28827: FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3636,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:04.873134  7029 maintenance_manager.cc:419] P 9cd7d9fd563942a0baaa0700ffb28827: Scheduling MajorDeltaCompactionOp(e39dc3c86bf446a3864f1a0dcea43b78): perf score=1.000000
I20260812 06:19:05.073716  6963 maintenance_manager.cc:643] P 9cd7d9fd563942a0baaa0700ffb28827: MajorDeltaCompactionOp(e39dc3c86bf446a3864f1a0dcea43b78) complete. Timing: real 0.200s	user 0.118s	sys 0.079s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877191,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":288,"lbm_read_time_us":14130,"lbm_reads_lt_1ms":673,"lbm_write_time_us":33807,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":3000}
I20260812 06:19:05.074481  7029 maintenance_manager.cc:419] P 9cd7d9fd563942a0baaa0700ffb28827: Scheduling FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78): perf score=14.095187
I20260812 06:19:05.116317  6963 maintenance_manager.cc:643] P 9cd7d9fd563942a0baaa0700ffb28827: FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78) complete. Timing: real 0.042s	user 0.027s	sys 0.013s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18683,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:05.116894  7029 maintenance_manager.cc:419] P 9cd7d9fd563942a0baaa0700ffb28827: Scheduling FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78): perf score=2.188937
I20260812 06:19:05.127815  6963 maintenance_manager.cc:643] P 9cd7d9fd563942a0baaa0700ffb28827: FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4232,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:05.128620  7029 maintenance_manager.cc:419] P 9cd7d9fd563942a0baaa0700ffb28827: Scheduling MajorDeltaCompactionOp(e39dc3c86bf446a3864f1a0dcea43b78): perf score=1.000000
I20260812 06:19:05.302405  6963 maintenance_manager.cc:643] P 9cd7d9fd563942a0baaa0700ffb28827: MajorDeltaCompactionOp(e39dc3c86bf446a3864f1a0dcea43b78) complete. Timing: real 0.174s	user 0.130s	sys 0.043s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":883,"lbm_read_time_us":11397,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30448,"lbm_writes_lt_1ms":543,"mutex_wait_us":118,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:05.303051  7029 maintenance_manager.cc:419] P 9cd7d9fd563942a0baaa0700ffb28827: Scheduling FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78): perf score=14.095187
I20260812 06:19:05.356500  6963 maintenance_manager.cc:643] P 9cd7d9fd563942a0baaa0700ffb28827: FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78) complete. Timing: real 0.053s	user 0.024s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20453,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:05.357215  7029 maintenance_manager.cc:419] P 9cd7d9fd563942a0baaa0700ffb28827: Scheduling FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78): perf score=2.188937
I20260812 06:19:05.375448  6963 maintenance_manager.cc:643] P 9cd7d9fd563942a0baaa0700ffb28827: FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78) complete. Timing: real 0.018s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6669,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:05.376190  7029 maintenance_manager.cc:419] P 9cd7d9fd563942a0baaa0700ffb28827: Scheduling MajorDeltaCompactionOp(e39dc3c86bf446a3864f1a0dcea43b78): perf score=1.000000
I20260812 06:19:05.541987  6963 maintenance_manager.cc:643] P 9cd7d9fd563942a0baaa0700ffb28827: MajorDeltaCompactionOp(e39dc3c86bf446a3864f1a0dcea43b78) complete. Timing: real 0.166s	user 0.113s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1009,"lbm_read_time_us":10373,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29668,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":96256,"update_count":2500}
I20260812 06:19:05.542611  7029 maintenance_manager.cc:419] P 9cd7d9fd563942a0baaa0700ffb28827: Scheduling FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78): perf score=14.095187
I20260812 06:19:05.606630  6963 maintenance_manager.cc:643] P 9cd7d9fd563942a0baaa0700ffb28827: FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78) complete. Timing: real 0.064s	user 0.027s	sys 0.031s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21349,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:05.607254  7029 maintenance_manager.cc:419] P 9cd7d9fd563942a0baaa0700ffb28827: Scheduling FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78): perf score=2.188937
I20260812 06:19:05.620373  6963 maintenance_manager.cc:643] P 9cd7d9fd563942a0baaa0700ffb28827: FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5280,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:05.620879  7029 maintenance_manager.cc:419] P 9cd7d9fd563942a0baaa0700ffb28827: Scheduling FlushMRSOp(e39dc3c86bf446a3864f1a0dcea43b78): perf score=1.000000
I20260812 06:19:05.663484  6963 maintenance_manager.cc:643] P 9cd7d9fd563942a0baaa0700ffb28827: FlushMRSOp(e39dc3c86bf446a3864f1a0dcea43b78) complete. Timing: real 0.042s	user 0.026s	sys 0.004s Metrics: {"bytes_written":1193507,"cfile_init":1,"dirs.queue_time_us":86,"dirs.run_cpu_time_us":239,"dirs.run_wall_time_us":1526,"drs_written":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1505,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:19:05.664173  7029 maintenance_manager.cc:419] P 9cd7d9fd563942a0baaa0700ffb28827: Scheduling LogGCOp(e39dc3c86bf446a3864f1a0dcea43b78): free 121459767 bytes of WAL
I20260812 06:19:05.664409  6963 log_reader.cc:385] T e39dc3c86bf446a3864f1a0dcea43b78: removed 12 log segments from log reader
I20260812 06:19:05.664451  6963 log.cc:1079] T e39dc3c86bf446a3864f1a0dcea43b78 P 9cd7d9fd563942a0baaa0700ffb28827: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/e39dc3c86bf446a3864f1a0dcea43b78/wal-000000027 (ops 129-133)
I20260812 06:19:05.664482  6963 log.cc:1079] T e39dc3c86bf446a3864f1a0dcea43b78 P 9cd7d9fd563942a0baaa0700ffb28827: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/e39dc3c86bf446a3864f1a0dcea43b78/wal-000000028 (ops 134-138)
I20260812 06:19:05.664546  6963 log.cc:1079] T e39dc3c86bf446a3864f1a0dcea43b78 P 9cd7d9fd563942a0baaa0700ffb28827: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/e39dc3c86bf446a3864f1a0dcea43b78/wal-000000029 (ops 139-143)
I20260812 06:19:05.664579  6963 log.cc:1079] T e39dc3c86bf446a3864f1a0dcea43b78 P 9cd7d9fd563942a0baaa0700ffb28827: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/e39dc3c86bf446a3864f1a0dcea43b78/wal-000000030 (ops 144-148)
I20260812 06:19:05.664623  6963 log.cc:1079] T e39dc3c86bf446a3864f1a0dcea43b78 P 9cd7d9fd563942a0baaa0700ffb28827: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/e39dc3c86bf446a3864f1a0dcea43b78/wal-000000031 (ops 149-153)
I20260812 06:19:05.664682  6963 log.cc:1079] T e39dc3c86bf446a3864f1a0dcea43b78 P 9cd7d9fd563942a0baaa0700ffb28827: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/e39dc3c86bf446a3864f1a0dcea43b78/wal-000000032 (ops 154-158)
I20260812 06:19:05.664726  6963 log.cc:1079] T e39dc3c86bf446a3864f1a0dcea43b78 P 9cd7d9fd563942a0baaa0700ffb28827: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/e39dc3c86bf446a3864f1a0dcea43b78/wal-000000033 (ops 159-163)
I20260812 06:19:05.664768  6963 log.cc:1079] T e39dc3c86bf446a3864f1a0dcea43b78 P 9cd7d9fd563942a0baaa0700ffb28827: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/e39dc3c86bf446a3864f1a0dcea43b78/wal-000000034 (ops 164-168)
I20260812 06:19:05.664809  6963 log.cc:1079] T e39dc3c86bf446a3864f1a0dcea43b78 P 9cd7d9fd563942a0baaa0700ffb28827: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/e39dc3c86bf446a3864f1a0dcea43b78/wal-000000035 (ops 169-173)
I20260812 06:19:05.664876  6963 log.cc:1079] T e39dc3c86bf446a3864f1a0dcea43b78 P 9cd7d9fd563942a0baaa0700ffb28827: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/e39dc3c86bf446a3864f1a0dcea43b78/wal-000000036 (ops 174-178)
I20260812 06:19:05.664916  6963 log.cc:1079] T e39dc3c86bf446a3864f1a0dcea43b78 P 9cd7d9fd563942a0baaa0700ffb28827: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/e39dc3c86bf446a3864f1a0dcea43b78/wal-000000037 (ops 179-183)
I20260812 06:19:05.664963  6963 log.cc:1079] T e39dc3c86bf446a3864f1a0dcea43b78 P 9cd7d9fd563942a0baaa0700ffb28827: Deleting log segment in path: /tmp/dist-test-taskVoWHY7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535294106-6648-0/minicluster-data/ts-0-root/wals/e39dc3c86bf446a3864f1a0dcea43b78/wal-000000038 (ops 184-188)
I20260812 06:19:05.691154  6963 maintenance_manager.cc:643] P 9cd7d9fd563942a0baaa0700ffb28827: LogGCOp(e39dc3c86bf446a3864f1a0dcea43b78) complete. Timing: real 0.027s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:19:05.691676  7029 maintenance_manager.cc:419] P 9cd7d9fd563942a0baaa0700ffb28827: Scheduling UndoDeltaBlockGCOp(e39dc3c86bf446a3864f1a0dcea43b78): 462 bytes on disk
I20260812 06:19:05.692117  6963 maintenance_manager.cc:643] P 9cd7d9fd563942a0baaa0700ffb28827: UndoDeltaBlockGCOp(e39dc3c86bf446a3864f1a0dcea43b78) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4}
I20260812 06:19:05.692654  7029 maintenance_manager.cc:419] P 9cd7d9fd563942a0baaa0700ffb28827: Scheduling FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78): perf score=2.188937
I20260812 06:19:05.715538  6963 maintenance_manager.cc:643] P 9cd7d9fd563942a0baaa0700ffb28827: FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78) complete. Timing: real 0.023s	user 0.002s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6313,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":500}
I20260812 06:19:05.716060  7029 maintenance_manager.cc:419] P 9cd7d9fd563942a0baaa0700ffb28827: Scheduling FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78): perf score=2.188937
I20260812 06:19:05.726552  6963 maintenance_manager.cc:643] P 9cd7d9fd563942a0baaa0700ffb28827: FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4037,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:05.727023  7029 maintenance_manager.cc:419] P 9cd7d9fd563942a0baaa0700ffb28827: Scheduling MajorDeltaCompactionOp(e39dc3c86bf446a3864f1a0dcea43b78): perf score=1.000000
I20260812 06:19:05.957762  6963 maintenance_manager.cc:643] P 9cd7d9fd563942a0baaa0700ffb28827: MajorDeltaCompactionOp(e39dc3c86bf446a3864f1a0dcea43b78) complete. Timing: real 0.231s	user 0.125s	sys 0.099s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979749,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":656,"lbm_read_time_us":15976,"lbm_reads_lt_1ms":774,"lbm_write_time_us":37299,"lbm_writes_lt_1ms":743,"mutex_wait_us":320,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":5248,"thread_start_us":82,"threads_started":1,"update_count":3500}
I20260812 06:19:05.958580  7029 maintenance_manager.cc:419] P 9cd7d9fd563942a0baaa0700ffb28827: Scheduling FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78): perf score=15.087375
I20260812 06:19:05.977456  6648 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.984s	user 1.848s	sys 0.197s
I20260812 06:19:06.026710  6648 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.049s	user 0.003s	sys 0.000s
I20260812 06:19:06.027259  6648 tablet_server.cc:179] TabletServer@127.6.126.1:0 shutting down...
I20260812 06:19:06.027189  6963 maintenance_manager.cc:643] P 9cd7d9fd563942a0baaa0700ffb28827: FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78) complete. Timing: real 0.067s	user 0.038s	sys 0.027s Metrics: {"bytes_written":17230388,"delete_count":0,"lbm_write_time_us":29598,"lbm_writes_lt_1ms":423,"reinsert_count":0,"update_count":2100}
I20260812 06:19:06.027809  7029 maintenance_manager.cc:419] P 9cd7d9fd563942a0baaa0700ffb28827: Scheduling FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78): perf score=2.188937
I20260812 06:19:06.039012  6963 maintenance_manager.cc:643] P 9cd7d9fd563942a0baaa0700ffb28827: FlushDeltaMemStoresOp(e39dc3c86bf446a3864f1a0dcea43b78) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":3282155,"delete_count":0,"lbm_write_time_us":3997,"lbm_writes_lt_1ms":83,"reinsert_count":0,"update_count":400}
I20260812 06:19:06.039582  6648 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:06.039799  6648 tablet_replica.cc:333] T e39dc3c86bf446a3864f1a0dcea43b78 P 9cd7d9fd563942a0baaa0700ffb28827: stopping tablet replica
I20260812 06:19:06.039937  6648 raft_consensus.cc:2243] T e39dc3c86bf446a3864f1a0dcea43b78 P 9cd7d9fd563942a0baaa0700ffb28827 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:06.040115  6648 raft_consensus.cc:2272] T e39dc3c86bf446a3864f1a0dcea43b78 P 9cd7d9fd563942a0baaa0700ffb28827 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:06.043502  6648 tablet_server.cc:196] TabletServer@127.6.126.1:0 shutdown complete.
I20260812 06:19:06.046384  6648 master.cc:562] Master@127.6.126.62:46815 shutting down...
I20260812 06:19:06.049626  6648 raft_consensus.cc:2243] T 00000000000000000000000000000000 P a266515a6697491bb01b976f04b5e5db [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:06.049805  6648 raft_consensus.cc:2272] T 00000000000000000000000000000000 P a266515a6697491bb01b976f04b5e5db [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:06.049904  6648 tablet_replica.cc:333] T 00000000000000000000000000000000 P a266515a6697491bb01b976f04b5e5db: stopping tablet replica
I20260812 06:19:06.062222  6648 master.cc:584] Master@127.6.126.62:46815 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5351 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10846 ms total)

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