[==========] 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:22.530812  9483 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.9.66.254:34393
I20260812 06:18:22.532104  9483 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:22.532869  9483 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:22.540186  9493 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:22.540280  9483 server_base.cc:1061] running on GCE node
W20260812 06:18:22.540207  9489 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:22.540529  9491 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:22.541074  9483 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:22.541226  9483 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:22.541289  9483 hybrid_clock.cc:648] HybridClock initialized: now 1786515502541286 us; error 0 us; skew 500 ppm
I20260812 06:18:22.543401  9483 webserver.cc:533] Webserver started at http://127.9.66.254:34697/ using document root <none> and password file <none>
I20260812 06:18:22.544072  9483 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:22.544167  9483 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:22.544443  9483 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:22.546344  9483 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502517496-9483-0/minicluster-data/master-0-root/instance:
uuid: "5ddcb540004b4072921f4fa14eb5c9a3"
format_stamp: "Formatted at 2026-08-12 06:18:22 on dist-test-slave-vxj2"
I20260812 06:18:22.550532  9483 fs_manager.cc:696] Time spent creating directory manager: real 0.004s	user 0.004s	sys 0.000s
I20260812 06:18:22.553292  9500 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:22.554704  9483 fs_manager.cc:730] Time spent opening block manager: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:22.554901  9483 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502517496-9483-0/minicluster-data/master-0-root
uuid: "5ddcb540004b4072921f4fa14eb5c9a3"
format_stamp: "Formatted at 2026-08-12 06:18:22 on dist-test-slave-vxj2"
I20260812 06:18:22.555056  9483 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502517496-9483-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502517496-9483-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502517496-9483-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:22.572822  9483 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:22.573796  9483 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:22.574007  9483 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:22.583880  9483 rpc_server.cc:307] RPC server started. Bound to: 127.9.66.254:34393
I20260812 06:18:22.583966  9560 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.9.66.254:34393 every 8 connection(s)
I20260812 06:18:22.586869  9561 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:22.593847  9561 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 5ddcb540004b4072921f4fa14eb5c9a3: Bootstrap starting.
I20260812 06:18:22.596628  9561 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 5ddcb540004b4072921f4fa14eb5c9a3: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:22.597806  9561 log.cc:826] T 00000000000000000000000000000000 P 5ddcb540004b4072921f4fa14eb5c9a3: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:22.600096  9561 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 5ddcb540004b4072921f4fa14eb5c9a3: No bootstrap required, opened a new log
I20260812 06:18:22.603471  9561 raft_consensus.cc:359] T 00000000000000000000000000000000 P 5ddcb540004b4072921f4fa14eb5c9a3 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5ddcb540004b4072921f4fa14eb5c9a3" member_type: VOTER }
I20260812 06:18:22.603693  9561 raft_consensus.cc:385] T 00000000000000000000000000000000 P 5ddcb540004b4072921f4fa14eb5c9a3 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:22.603739  9561 raft_consensus.cc:740] T 00000000000000000000000000000000 P 5ddcb540004b4072921f4fa14eb5c9a3 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 5ddcb540004b4072921f4fa14eb5c9a3, State: Initialized, Role: FOLLOWER
I20260812 06:18:22.604542  9561 consensus_queue.cc:260] T 00000000000000000000000000000000 P 5ddcb540004b4072921f4fa14eb5c9a3 [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: "5ddcb540004b4072921f4fa14eb5c9a3" member_type: VOTER }
I20260812 06:18:22.604712  9561 raft_consensus.cc:399] T 00000000000000000000000000000000 P 5ddcb540004b4072921f4fa14eb5c9a3 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:22.604815  9561 raft_consensus.cc:493] T 00000000000000000000000000000000 P 5ddcb540004b4072921f4fa14eb5c9a3 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:22.604977  9561 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 5ddcb540004b4072921f4fa14eb5c9a3 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:22.605998  9561 raft_consensus.cc:515] T 00000000000000000000000000000000 P 5ddcb540004b4072921f4fa14eb5c9a3 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5ddcb540004b4072921f4fa14eb5c9a3" member_type: VOTER }
I20260812 06:18:22.606549  9561 leader_election.cc:304] T 00000000000000000000000000000000 P 5ddcb540004b4072921f4fa14eb5c9a3 [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: 5ddcb540004b4072921f4fa14eb5c9a3; no voters: 
I20260812 06:18:22.606940  9561 leader_election.cc:290] T 00000000000000000000000000000000 P 5ddcb540004b4072921f4fa14eb5c9a3 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:22.607209  9564 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 5ddcb540004b4072921f4fa14eb5c9a3 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:22.607499  9564 raft_consensus.cc:697] T 00000000000000000000000000000000 P 5ddcb540004b4072921f4fa14eb5c9a3 [term 1 LEADER]: Becoming Leader. State: Replica: 5ddcb540004b4072921f4fa14eb5c9a3, State: Running, Role: LEADER
I20260812 06:18:22.607944  9564 consensus_queue.cc:237] T 00000000000000000000000000000000 P 5ddcb540004b4072921f4fa14eb5c9a3 [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: "5ddcb540004b4072921f4fa14eb5c9a3" member_type: VOTER }
I20260812 06:18:22.608503  9561 sys_catalog.cc:565] T 00000000000000000000000000000000 P 5ddcb540004b4072921f4fa14eb5c9a3 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:22.610199  9567 sys_catalog.cc:455] T 00000000000000000000000000000000 P 5ddcb540004b4072921f4fa14eb5c9a3 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 5ddcb540004b4072921f4fa14eb5c9a3. Latest consensus state: current_term: 1 leader_uuid: "5ddcb540004b4072921f4fa14eb5c9a3" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5ddcb540004b4072921f4fa14eb5c9a3" member_type: VOTER } }
I20260812 06:18:22.610242  9565 sys_catalog.cc:455] T 00000000000000000000000000000000 P 5ddcb540004b4072921f4fa14eb5c9a3 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "5ddcb540004b4072921f4fa14eb5c9a3" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5ddcb540004b4072921f4fa14eb5c9a3" member_type: VOTER } }
I20260812 06:18:22.610358  9567 sys_catalog.cc:458] T 00000000000000000000000000000000 P 5ddcb540004b4072921f4fa14eb5c9a3 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:22.610357  9565 sys_catalog.cc:458] T 00000000000000000000000000000000 P 5ddcb540004b4072921f4fa14eb5c9a3 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:22.610831  9575 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:22.613898  9575 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:22.614332  9483 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:22.620951  9575 catalog_manager.cc:1383] Generated new cluster ID: 70e132b836334d97a7b07289e2a0149c
I20260812 06:18:22.621088  9575 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:22.632854  9575 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:22.633908  9575 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:22.644941  9575 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 5ddcb540004b4072921f4fa14eb5c9a3: Generated new TSK 0
I20260812 06:18:22.645735  9575 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:22.647364  9483 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:22.650285  9587 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:22.650316  9588 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:22.650327  9590 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:22.650915  9483 server_base.cc:1061] running on GCE node
I20260812 06:18:22.651109  9483 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:22.651160  9483 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:22.651185  9483 hybrid_clock.cc:648] HybridClock initialized: now 1786515502651184 us; error 0 us; skew 500 ppm
I20260812 06:18:22.652186  9483 webserver.cc:533] Webserver started at http://127.9.66.193:36349/ using document root <none> and password file <none>
I20260812 06:18:22.652386  9483 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:22.652457  9483 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:22.652545  9483 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:22.652978  9483 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502517496-9483-0/minicluster-data/ts-0-root/instance:
uuid: "0b3e9d4cdb694b268a1d442980d26b4e"
format_stamp: "Formatted at 2026-08-12 06:18:22 on dist-test-slave-vxj2"
I20260812 06:18:22.654649  9483 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:22.655776  9595 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:22.656057  9483 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:22.656136  9483 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502517496-9483-0/minicluster-data/ts-0-root
uuid: "0b3e9d4cdb694b268a1d442980d26b4e"
format_stamp: "Formatted at 2026-08-12 06:18:22 on dist-test-slave-vxj2"
I20260812 06:18:22.656234  9483 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502517496-9483-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502517496-9483-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502517496-9483-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:22.690196  9483 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:22.690742  9483 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:22.691319  9483 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:22.692301  9483 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:22.692365  9483 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:22.692512  9483 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:22.692597  9483 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:22.700881  9483 rpc_server.cc:307] RPC server started. Bound to: 127.9.66.193:38657
I20260812 06:18:22.700919  9672 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.9.66.193:38657 every 8 connection(s)
I20260812 06:18:22.714113  9674 heartbeater.cc:344] Connected to a master server at 127.9.66.254:34393
I20260812 06:18:22.714450  9674 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:22.715025  9674 heartbeater.cc:507] Master 127.9.66.254:34393 requested a full tablet report, sending...
I20260812 06:18:22.716964  9520 ts_manager.cc:194] Registered new tserver with Master: 0b3e9d4cdb694b268a1d442980d26b4e (127.9.66.193:38657)
I20260812 06:18:22.717078  9483 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.015338949s
I20260812 06:18:22.718720  9520 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:34632
I20260812 06:18:22.728405  9520 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:34642:
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:22.743017  9630 tablet_service.cc:1511] Processing CreateTablet for tablet 3e71bc732628417daa36ca391083dc13 (DEFAULT_TABLE table=heavy-update-compaction-test [id=cf800de203994698a15193dd04b1cf6a]), partition=
I20260812 06:18:22.743552  9630 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 3e71bc732628417daa36ca391083dc13. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:22.746052  9689 tablet_bootstrap.cc:492] T 3e71bc732628417daa36ca391083dc13 P 0b3e9d4cdb694b268a1d442980d26b4e: Bootstrap starting.
I20260812 06:18:22.747327  9689 tablet_bootstrap.cc:654] T 3e71bc732628417daa36ca391083dc13 P 0b3e9d4cdb694b268a1d442980d26b4e: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:22.748556  9689 tablet_bootstrap.cc:492] T 3e71bc732628417daa36ca391083dc13 P 0b3e9d4cdb694b268a1d442980d26b4e: No bootstrap required, opened a new log
I20260812 06:18:22.748682  9689 ts_tablet_manager.cc:1403] T 3e71bc732628417daa36ca391083dc13 P 0b3e9d4cdb694b268a1d442980d26b4e: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:18:22.749207  9689 raft_consensus.cc:359] T 3e71bc732628417daa36ca391083dc13 P 0b3e9d4cdb694b268a1d442980d26b4e [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0b3e9d4cdb694b268a1d442980d26b4e" member_type: VOTER last_known_addr { host: "127.9.66.193" port: 38657 } }
I20260812 06:18:22.749347  9689 raft_consensus.cc:385] T 3e71bc732628417daa36ca391083dc13 P 0b3e9d4cdb694b268a1d442980d26b4e [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:22.749399  9689 raft_consensus.cc:740] T 3e71bc732628417daa36ca391083dc13 P 0b3e9d4cdb694b268a1d442980d26b4e [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 0b3e9d4cdb694b268a1d442980d26b4e, State: Initialized, Role: FOLLOWER
I20260812 06:18:22.749557  9689 consensus_queue.cc:260] T 3e71bc732628417daa36ca391083dc13 P 0b3e9d4cdb694b268a1d442980d26b4e [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: "0b3e9d4cdb694b268a1d442980d26b4e" member_type: VOTER last_known_addr { host: "127.9.66.193" port: 38657 } }
I20260812 06:18:22.749681  9689 raft_consensus.cc:399] T 3e71bc732628417daa36ca391083dc13 P 0b3e9d4cdb694b268a1d442980d26b4e [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:22.749732  9689 raft_consensus.cc:493] T 3e71bc732628417daa36ca391083dc13 P 0b3e9d4cdb694b268a1d442980d26b4e [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:22.749787  9689 raft_consensus.cc:3060] T 3e71bc732628417daa36ca391083dc13 P 0b3e9d4cdb694b268a1d442980d26b4e [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:22.750671  9689 raft_consensus.cc:515] T 3e71bc732628417daa36ca391083dc13 P 0b3e9d4cdb694b268a1d442980d26b4e [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0b3e9d4cdb694b268a1d442980d26b4e" member_type: VOTER last_known_addr { host: "127.9.66.193" port: 38657 } }
I20260812 06:18:22.750838  9689 leader_election.cc:304] T 3e71bc732628417daa36ca391083dc13 P 0b3e9d4cdb694b268a1d442980d26b4e [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: 0b3e9d4cdb694b268a1d442980d26b4e; no voters: 
I20260812 06:18:22.751116  9689 leader_election.cc:290] T 3e71bc732628417daa36ca391083dc13 P 0b3e9d4cdb694b268a1d442980d26b4e [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:22.751230  9692 raft_consensus.cc:2804] T 3e71bc732628417daa36ca391083dc13 P 0b3e9d4cdb694b268a1d442980d26b4e [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:22.751659  9692 raft_consensus.cc:697] T 3e71bc732628417daa36ca391083dc13 P 0b3e9d4cdb694b268a1d442980d26b4e [term 1 LEADER]: Becoming Leader. State: Replica: 0b3e9d4cdb694b268a1d442980d26b4e, State: Running, Role: LEADER
I20260812 06:18:22.751716  9689 ts_tablet_manager.cc:1434] T 3e71bc732628417daa36ca391083dc13 P 0b3e9d4cdb694b268a1d442980d26b4e: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:22.751863  9692 consensus_queue.cc:237] T 3e71bc732628417daa36ca391083dc13 P 0b3e9d4cdb694b268a1d442980d26b4e [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: "0b3e9d4cdb694b268a1d442980d26b4e" member_type: VOTER last_known_addr { host: "127.9.66.193" port: 38657 } }
I20260812 06:18:22.751987  9674 heartbeater.cc:499] Master 127.9.66.254:34393 was elected leader, sending a full tablet report...
I20260812 06:18:22.754849  9520 catalog_manager.cc:5719] T 3e71bc732628417daa36ca391083dc13 P 0b3e9d4cdb694b268a1d442980d26b4e reported cstate change: term changed from 0 to 1, leader changed from <none> to 0b3e9d4cdb694b268a1d442980d26b4e (127.9.66.193). New cstate: current_term: 1 leader_uuid: "0b3e9d4cdb694b268a1d442980d26b4e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0b3e9d4cdb694b268a1d442980d26b4e" member_type: VOTER last_known_addr { host: "127.9.66.193" port: 38657 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:22.827289  9483 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.062s	user 0.023s	sys 0.005s
I20260812 06:18:22.952702  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling FlushMRSOp(3e71bc732628417daa36ca391083dc13): perf score=15.086190
I20260812 06:18:23.142894  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: FlushMRSOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.190s	user 0.142s	sys 0.044s Metrics: {"bytes_written":13292061,"cfile_init":1,"compiler_manager_pool.queue_time_us":217,"delete_count":0,"dirs.queue_time_us":52,"dirs.run_cpu_time_us":251,"dirs.run_wall_time_us":948,"drs_written":1,"lbm_read_time_us":302,"lbm_reads_lt_1ms":4,"lbm_write_time_us":45784,"lbm_writes_lt_1ms":681,"mutex_wait_us":178,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"spinlock_wait_cycles":156544,"thread_start_us":147,"threads_started":1,"update_count":1620}
I20260812 06:18:23.144287  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling LogGCOp(3e71bc732628417daa36ca391083dc13): free 11976772 bytes of WAL
I20260812 06:18:23.144620  9604 log_reader.cc:385] T 3e71bc732628417daa36ca391083dc13: removed 1 log segments from log reader
I20260812 06:18:23.144687  9604 log.cc:1079] T 3e71bc732628417daa36ca391083dc13 P 0b3e9d4cdb694b268a1d442980d26b4e: Deleting log segment in path: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502517496-9483-0/minicluster-data/ts-0-root/wals/3e71bc732628417daa36ca391083dc13/wal-000000001 (ops 1-6)
I20260812 06:18:23.148399  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: LogGCOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.004s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:18:23.148972  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling UndoDeltaBlockGCOp(3e71bc732628417daa36ca391083dc13): 12308959 bytes on disk
I20260812 06:18:23.149695  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: UndoDeltaBlockGCOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":75,"lbm_reads_lt_1ms":4}
I20260812 06:18:23.150225  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13): perf score=3.181125
I20260812 06:18:23.170652  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.020s	user 0.018s	sys 0.001s Metrics: {"bytes_written":5046218,"delete_count":0,"lbm_write_time_us":8199,"lbm_writes_lt_1ms":126,"reinsert_count":0,"update_count":615}
I20260812 06:18:23.171236  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13): perf score=1.196750
I20260812 06:18:23.182119  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.011s	user 0.004s	sys 0.006s Metrics: {"bytes_written":2174479,"delete_count":0,"lbm_write_time_us":3420,"lbm_writes_lt_1ms":56,"reinsert_count":0,"update_count":265}
I20260812 06:18:23.182660  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling MajorDeltaCompactionOp(3e71bc732628417daa36ca391083dc13): perf score=1.000000
I20260812 06:18:23.384877  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: MajorDeltaCompactionOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.202s	user 0.142s	sys 0.054s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733793,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1006,"lbm_read_time_us":14158,"lbm_reads_lt_1ms":561,"lbm_write_time_us":33624,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2176,"thread_start_us":365,"threads_started":5,"update_count":2500}
I20260812 06:18:23.385720  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13): perf score=11.118625
I20260812 06:18:23.425829  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.040s	user 0.028s	sys 0.011s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":17490,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:23.426443  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13): perf score=2.188937
I20260812 06:18:23.443567  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.017s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4777,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:23.444236  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling MajorDeltaCompactionOp(3e71bc732628417daa36ca391083dc13): perf score=1.000000
I20260812 06:18:23.580991  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: MajorDeltaCompactionOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.137s	user 0.116s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631303,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":966,"lbm_read_time_us":8137,"lbm_reads_lt_1ms":468,"lbm_write_time_us":27142,"lbm_writes_lt_1ms":443,"mutex_wait_us":48,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10624,"update_count":2000}
I20260812 06:18:23.581833  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13): perf score=10.126437
I20260812 06:18:23.628311  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.046s	user 0.030s	sys 0.008s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17555,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:23.628854  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13): perf score=2.188937
I20260812 06:18:23.641062  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4273,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:23.641819  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling MajorDeltaCompactionOp(3e71bc732628417daa36ca391083dc13): perf score=1.000000
I20260812 06:18:23.773517  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: MajorDeltaCompactionOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.131s	user 0.099s	sys 0.032s 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":282,"lbm_read_time_us":9682,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24109,"lbm_writes_lt_1ms":443,"mutex_wait_us":52,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:18:23.774114  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13): perf score=10.126437
I20260812 06:18:23.832549  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.058s	user 0.022s	sys 0.019s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15728,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:23.833200  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13): perf score=2.188937
I20260812 06:18:23.844106  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4191,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:23.844584  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling MajorDeltaCompactionOp(3e71bc732628417daa36ca391083dc13): perf score=1.000000
I20260812 06:18:24.002731  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: MajorDeltaCompactionOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.158s	user 0.122s	sys 0.036s 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":334,"lbm_read_time_us":11127,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23470,"lbm_writes_lt_1ms":443,"mutex_wait_us":36,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3200,"update_count":2000}
I20260812 06:18:24.003394  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13): perf score=10.126437
I20260812 06:18:24.058815  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.055s	user 0.028s	sys 0.012s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18276,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:24.059716  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13): perf score=2.188937
I20260812 06:18:24.072791  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4855,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:24.073633  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling MajorDeltaCompactionOp(3e71bc732628417daa36ca391083dc13): perf score=1.000000
I20260812 06:18:24.205627  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: MajorDeltaCompactionOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.132s	user 0.118s	sys 0.013s 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":1089,"lbm_read_time_us":8215,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26219,"lbm_writes_lt_1ms":443,"mutex_wait_us":19,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14720,"update_count":2000}
I20260812 06:18:24.206408  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13): perf score=10.126437
I20260812 06:18:24.252242  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.046s	user 0.021s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17460,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:24.252828  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13): perf score=2.188937
I20260812 06:18:24.264310  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4422,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:24.265033  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling MajorDeltaCompactionOp(3e71bc732628417daa36ca391083dc13): perf score=1.000000
I20260812 06:18:24.398725  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: MajorDeltaCompactionOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.133s	user 0.110s	sys 0.022s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":446,"lbm_read_time_us":10128,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26353,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2944,"update_count":2000}
I20260812 06:18:24.399430  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13): perf score=10.126437
I20260812 06:18:24.450762  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.051s	user 0.035s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18972,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:24.451484  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling FlushMRSOp(3e71bc732628417daa36ca391083dc13): perf score=1.000000
I20260812 06:18:24.489624  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: FlushMRSOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.038s	user 0.026s	sys 0.004s Metrics: {"bytes_written":1193504,"cfile_init":1,"dirs.queue_time_us":89,"dirs.run_cpu_time_us":319,"dirs.run_wall_time_us":1854,"drs_written":1,"lbm_read_time_us":82,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1947,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:24.490731  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling LogGCOp(3e71bc732628417daa36ca391083dc13): free 112692367 bytes of WAL
I20260812 06:18:24.491088  9604 log_reader.cc:385] T 3e71bc732628417daa36ca391083dc13: removed 11 log segments from log reader
I20260812 06:18:24.491196  9604 log.cc:1079] T 3e71bc732628417daa36ca391083dc13 P 0b3e9d4cdb694b268a1d442980d26b4e: Deleting log segment in path: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502517496-9483-0/minicluster-data/ts-0-root/wals/3e71bc732628417daa36ca391083dc13/wal-000000002 (ops 7-11)
I20260812 06:18:24.491286  9604 log.cc:1079] T 3e71bc732628417daa36ca391083dc13 P 0b3e9d4cdb694b268a1d442980d26b4e: Deleting log segment in path: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502517496-9483-0/minicluster-data/ts-0-root/wals/3e71bc732628417daa36ca391083dc13/wal-000000003 (ops 12-16)
I20260812 06:18:24.491376  9604 log.cc:1079] T 3e71bc732628417daa36ca391083dc13 P 0b3e9d4cdb694b268a1d442980d26b4e: Deleting log segment in path: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502517496-9483-0/minicluster-data/ts-0-root/wals/3e71bc732628417daa36ca391083dc13/wal-000000004 (ops 17-21)
I20260812 06:18:24.491444  9604 log.cc:1079] T 3e71bc732628417daa36ca391083dc13 P 0b3e9d4cdb694b268a1d442980d26b4e: Deleting log segment in path: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502517496-9483-0/minicluster-data/ts-0-root/wals/3e71bc732628417daa36ca391083dc13/wal-000000005 (ops 22-26)
I20260812 06:18:24.491510  9604 log.cc:1079] T 3e71bc732628417daa36ca391083dc13 P 0b3e9d4cdb694b268a1d442980d26b4e: Deleting log segment in path: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502517496-9483-0/minicluster-data/ts-0-root/wals/3e71bc732628417daa36ca391083dc13/wal-000000006 (ops 27-31)
I20260812 06:18:24.491573  9604 log.cc:1079] T 3e71bc732628417daa36ca391083dc13 P 0b3e9d4cdb694b268a1d442980d26b4e: Deleting log segment in path: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502517496-9483-0/minicluster-data/ts-0-root/wals/3e71bc732628417daa36ca391083dc13/wal-000000007 (ops 32-36)
I20260812 06:18:24.491639  9604 log.cc:1079] T 3e71bc732628417daa36ca391083dc13 P 0b3e9d4cdb694b268a1d442980d26b4e: Deleting log segment in path: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502517496-9483-0/minicluster-data/ts-0-root/wals/3e71bc732628417daa36ca391083dc13/wal-000000008 (ops 37-41)
I20260812 06:18:24.491701  9604 log.cc:1079] T 3e71bc732628417daa36ca391083dc13 P 0b3e9d4cdb694b268a1d442980d26b4e: Deleting log segment in path: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502517496-9483-0/minicluster-data/ts-0-root/wals/3e71bc732628417daa36ca391083dc13/wal-000000009 (ops 42-46)
I20260812 06:18:24.491770  9604 log.cc:1079] T 3e71bc732628417daa36ca391083dc13 P 0b3e9d4cdb694b268a1d442980d26b4e: Deleting log segment in path: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502517496-9483-0/minicluster-data/ts-0-root/wals/3e71bc732628417daa36ca391083dc13/wal-000000010 (ops 47-51)
I20260812 06:18:24.491833  9604 log.cc:1079] T 3e71bc732628417daa36ca391083dc13 P 0b3e9d4cdb694b268a1d442980d26b4e: Deleting log segment in path: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502517496-9483-0/minicluster-data/ts-0-root/wals/3e71bc732628417daa36ca391083dc13/wal-000000011 (ops 52-56)
I20260812 06:18:24.491900  9604 log.cc:1079] T 3e71bc732628417daa36ca391083dc13 P 0b3e9d4cdb694b268a1d442980d26b4e: Deleting log segment in path: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502517496-9483-0/minicluster-data/ts-0-root/wals/3e71bc732628417daa36ca391083dc13/wal-000000012 (ops 57-61)
I20260812 06:18:24.515897  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: LogGCOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.025s	user 0.003s	sys 0.019s Metrics: {}
I20260812 06:18:24.516516  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13): perf score=6.157687
I20260812 06:18:24.543196  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.026s	user 0.024s	sys 0.000s Metrics: {"bytes_written":7548691,"delete_count":0,"lbm_write_time_us":10491,"lbm_writes_lt_1ms":187,"reinsert_count":0,"update_count":920}
I20260812 06:18:24.543992  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling LogGCOp(3e71bc732628417daa36ca391083dc13): free 12017932 bytes of WAL
I20260812 06:18:24.544391  9604 log_reader.cc:385] T 3e71bc732628417daa36ca391083dc13: removed 1 log segments from log reader
I20260812 06:18:24.544482  9604 log.cc:1079] T 3e71bc732628417daa36ca391083dc13 P 0b3e9d4cdb694b268a1d442980d26b4e: Deleting log segment in path: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502517496-9483-0/minicluster-data/ts-0-root/wals/3e71bc732628417daa36ca391083dc13/wal-000000013 (ops 62-66)
I20260812 06:18:24.548009  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: LogGCOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.004s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:18:24.548482  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling MajorDeltaCompactionOp(3e71bc732628417daa36ca391083dc13): perf score=1.000000
I20260812 06:18:24.722201  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: MajorDeltaCompactionOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.173s	user 0.113s	sys 0.047s Metrics: {"cfile_cache_miss":516,"cfile_cache_miss_bytes":24077338,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":418,"lbm_read_time_us":10550,"lbm_reads_lt_1ms":552,"lbm_write_time_us":29351,"lbm_writes_lt_1ms":527,"mutex_wait_us":29,"peak_mem_usage":60378572,"reinsert_count":0,"spinlock_wait_cycles":98944,"thread_start_us":84,"threads_started":1,"update_count":2420}
I20260812 06:18:24.723068  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13): perf score=15.087375
I20260812 06:18:24.788847  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.066s	user 0.023s	sys 0.039s Metrics: {"bytes_written":17066296,"delete_count":0,"lbm_write_time_us":26236,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":418,"reinsert_count":0,"update_count":2080}
I20260812 06:18:24.789533  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling UndoDeltaBlockGCOp(3e71bc732628417daa36ca391083dc13): 462 bytes on disk
I20260812 06:18:24.790055  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: UndoDeltaBlockGCOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":92,"lbm_reads_lt_1ms":4}
I20260812 06:18:24.790555  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13): perf score=2.188937
I20260812 06:18:24.801609  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4158,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:24.802132  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling MajorDeltaCompactionOp(3e71bc732628417daa36ca391083dc13): perf score=1.000000
I20260812 06:18:24.985756  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: MajorDeltaCompactionOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.183s	user 0.109s	sys 0.068s Metrics: {"cfile_cache_miss":548,"cfile_cache_miss_bytes":25390118,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":156,"lbm_read_time_us":14314,"lbm_reads_lt_1ms":588,"lbm_write_time_us":29507,"lbm_writes_lt_1ms":559,"mutex_wait_us":82,"peak_mem_usage":64812844,"reinsert_count":0,"update_count":2580}
I20260812 06:18:24.986536  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13): perf score=11.118625
I20260812 06:18:25.025063  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.038s	user 0.023s	sys 0.011s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16728,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:25.026178  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13): perf score=2.188937
I20260812 06:18:25.049593  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.023s	user 0.002s	sys 0.019s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5649,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:25.050118  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13): perf score=1.000000
I20260812 06:18:25.059768  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.009s	user 0.004s	sys 0.000s Metrics: {"bytes_written":1395006,"delete_count":0,"lbm_write_time_us":1436,"lbm_writes_lt_1ms":37,"reinsert_count":0,"update_count":170}
I20260812 06:18:25.060238  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13): perf score=1.196750
I20260812 06:18:25.068446  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.008s	user 0.000s	sys 0.006s Metrics: {"bytes_written":2707805,"delete_count":0,"lbm_write_time_us":2827,"lbm_writes_lt_1ms":69,"reinsert_count":0,"update_count":330}
I20260812 06:18:25.068938  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling MajorDeltaCompactionOp(3e71bc732628417daa36ca391083dc13): perf score=1.000000
I20260812 06:18:25.247326  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: MajorDeltaCompactionOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.178s	user 0.111s	sys 0.065s Metrics: {"cfile_cache_miss":534,"cfile_cache_miss_bytes":24733859,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":216,"lbm_read_time_us":12777,"lbm_reads_lt_1ms":574,"lbm_write_time_us":31360,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2500}
I20260812 06:18:25.248003  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13): perf score=10.126437
I20260812 06:18:25.296146  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.048s	user 0.024s	sys 0.009s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16273,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:25.296912  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13): perf score=2.188937
I20260812 06:18:25.311095  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.013s	user 0.012s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4979,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:25.311789  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling MajorDeltaCompactionOp(3e71bc732628417daa36ca391083dc13): perf score=1.000000
I20260812 06:18:25.495719  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: MajorDeltaCompactionOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.184s	user 0.139s	sys 0.036s 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":259,"lbm_read_time_us":10877,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27066,"lbm_writes_lt_1ms":443,"mutex_wait_us":49,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6016,"update_count":2000}
I20260812 06:18:25.496577  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13): perf score=14.095187
I20260812 06:18:25.556165  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.059s	user 0.024s	sys 0.031s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25969,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:25.556739  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13): perf score=2.188937
I20260812 06:18:25.569136  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4110,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:25.569947  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling MajorDeltaCompactionOp(3e71bc732628417daa36ca391083dc13): perf score=1.000000
I20260812 06:18:25.750859  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: MajorDeltaCompactionOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.181s	user 0.137s	sys 0.031s 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":464,"lbm_read_time_us":11388,"lbm_reads_lt_1ms":572,"lbm_write_time_us":35136,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:25.751431  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13): perf score=14.095187
I20260812 06:18:25.814939  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.063s	user 0.039s	sys 0.016s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":25753,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:25.815471  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13): perf score=2.188937
I20260812 06:18:25.827344  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.012s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4147,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:25.828074  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling MajorDeltaCompactionOp(3e71bc732628417daa36ca391083dc13): perf score=1.000000
I20260812 06:18:26.003275  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: MajorDeltaCompactionOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.175s	user 0.138s	sys 0.035s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733721,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":439,"lbm_read_time_us":11646,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34600,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8192,"update_count":2500}
I20260812 06:18:26.004599  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13): perf score=12.110812
I20260812 06:18:26.051865  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.047s	user 0.037s	sys 0.004s Metrics: {"bytes_written":13743339,"delete_count":0,"lbm_write_time_us":18390,"lbm_writes_lt_1ms":338,"reinsert_count":0,"update_count":1675}
I20260812 06:18:26.052433  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13): perf score=1.196750
I20260812 06:18:26.073130  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.021s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3077034,"delete_count":0,"lbm_write_time_us":3302,"lbm_writes_lt_1ms":78,"reinsert_count":0,"update_count":375}
I20260812 06:18:26.073788  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13): perf score=2.188937
I20260812 06:18:26.089859  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.016s	user 0.006s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5974,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:26.090636  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling FlushMRSOp(3e71bc732628417daa36ca391083dc13): perf score=1.000000
I20260812 06:18:26.124377  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: FlushMRSOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.033s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":81,"dirs.run_cpu_time_us":235,"dirs.run_wall_time_us":1973,"drs_written":1,"lbm_read_time_us":91,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1786,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:26.125113  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling LogGCOp(3e71bc732628417daa36ca391083dc13): free 121459511 bytes of WAL
I20260812 06:18:26.125424  9604 log_reader.cc:385] T 3e71bc732628417daa36ca391083dc13: removed 12 log segments from log reader
I20260812 06:18:26.125471  9604 log.cc:1079] T 3e71bc732628417daa36ca391083dc13 P 0b3e9d4cdb694b268a1d442980d26b4e: Deleting log segment in path: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502517496-9483-0/minicluster-data/ts-0-root/wals/3e71bc732628417daa36ca391083dc13/wal-000000014 (ops 67-71)
I20260812 06:18:26.125502  9604 log.cc:1079] T 3e71bc732628417daa36ca391083dc13 P 0b3e9d4cdb694b268a1d442980d26b4e: Deleting log segment in path: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502517496-9483-0/minicluster-data/ts-0-root/wals/3e71bc732628417daa36ca391083dc13/wal-000000015 (ops 72-76)
I20260812 06:18:26.125567  9604 log.cc:1079] T 3e71bc732628417daa36ca391083dc13 P 0b3e9d4cdb694b268a1d442980d26b4e: Deleting log segment in path: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502517496-9483-0/minicluster-data/ts-0-root/wals/3e71bc732628417daa36ca391083dc13/wal-000000016 (ops 77-81)
I20260812 06:18:26.125613  9604 log.cc:1079] T 3e71bc732628417daa36ca391083dc13 P 0b3e9d4cdb694b268a1d442980d26b4e: Deleting log segment in path: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502517496-9483-0/minicluster-data/ts-0-root/wals/3e71bc732628417daa36ca391083dc13/wal-000000017 (ops 82-86)
I20260812 06:18:26.125656  9604 log.cc:1079] T 3e71bc732628417daa36ca391083dc13 P 0b3e9d4cdb694b268a1d442980d26b4e: Deleting log segment in path: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502517496-9483-0/minicluster-data/ts-0-root/wals/3e71bc732628417daa36ca391083dc13/wal-000000018 (ops 87-91)
I20260812 06:18:26.125715  9604 log.cc:1079] T 3e71bc732628417daa36ca391083dc13 P 0b3e9d4cdb694b268a1d442980d26b4e: Deleting log segment in path: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502517496-9483-0/minicluster-data/ts-0-root/wals/3e71bc732628417daa36ca391083dc13/wal-000000019 (ops 92-96)
I20260812 06:18:26.125756  9604 log.cc:1079] T 3e71bc732628417daa36ca391083dc13 P 0b3e9d4cdb694b268a1d442980d26b4e: Deleting log segment in path: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502517496-9483-0/minicluster-data/ts-0-root/wals/3e71bc732628417daa36ca391083dc13/wal-000000020 (ops 97-101)
I20260812 06:18:26.125793  9604 log.cc:1079] T 3e71bc732628417daa36ca391083dc13 P 0b3e9d4cdb694b268a1d442980d26b4e: Deleting log segment in path: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502517496-9483-0/minicluster-data/ts-0-root/wals/3e71bc732628417daa36ca391083dc13/wal-000000021 (ops 102-106)
I20260812 06:18:26.125840  9604 log.cc:1079] T 3e71bc732628417daa36ca391083dc13 P 0b3e9d4cdb694b268a1d442980d26b4e: Deleting log segment in path: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502517496-9483-0/minicluster-data/ts-0-root/wals/3e71bc732628417daa36ca391083dc13/wal-000000022 (ops 107-111)
I20260812 06:18:26.125880  9604 log.cc:1079] T 3e71bc732628417daa36ca391083dc13 P 0b3e9d4cdb694b268a1d442980d26b4e: Deleting log segment in path: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502517496-9483-0/minicluster-data/ts-0-root/wals/3e71bc732628417daa36ca391083dc13/wal-000000023 (ops 112-116)
I20260812 06:18:26.125917  9604 log.cc:1079] T 3e71bc732628417daa36ca391083dc13 P 0b3e9d4cdb694b268a1d442980d26b4e: Deleting log segment in path: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502517496-9483-0/minicluster-data/ts-0-root/wals/3e71bc732628417daa36ca391083dc13/wal-000000024 (ops 117-121)
I20260812 06:18:26.125957  9604 log.cc:1079] T 3e71bc732628417daa36ca391083dc13 P 0b3e9d4cdb694b268a1d442980d26b4e: Deleting log segment in path: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502517496-9483-0/minicluster-data/ts-0-root/wals/3e71bc732628417daa36ca391083dc13/wal-000000025 (ops 122-126)
I20260812 06:18:26.153779  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: LogGCOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.028s	user 0.000s	sys 0.028s Metrics: {}
I20260812 06:18:26.154590  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling UndoDeltaBlockGCOp(3e71bc732628417daa36ca391083dc13): 472 bytes on disk
I20260812 06:18:26.155093  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: UndoDeltaBlockGCOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4}
I20260812 06:18:26.155611  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13): perf score=3.181125
I20260812 06:18:26.172464  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.017s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":4753,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:26.172935  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13): perf score=2.188937
I20260812 06:18:26.184897  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3961,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:26.185499  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling MajorDeltaCompactionOp(3e71bc732628417daa36ca391083dc13): perf score=1.000000
I20260812 06:18:26.412523  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: MajorDeltaCompactionOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.227s	user 0.147s	sys 0.080s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32938864,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":290,"lbm_read_time_us":17204,"lbm_reads_lt_1ms":775,"lbm_write_time_us":42438,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":15872,"thread_start_us":111,"threads_started":1,"update_count":3500}
I20260812 06:18:26.413445  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13): perf score=15.087375
I20260812 06:18:26.479557  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.066s	user 0.031s	sys 0.020s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":24836,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":410,"reinsert_count":0,"update_count":2050}
I20260812 06:18:26.480121  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13): perf score=6.157687
I20260812 06:18:26.508419  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.028s	user 0.018s	sys 0.005s Metrics: {"bytes_written":7794836,"delete_count":0,"lbm_write_time_us":10096,"lbm_writes_lt_1ms":193,"reinsert_count":0,"update_count":950}
I20260812 06:18:26.509100  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling MajorDeltaCompactionOp(3e71bc732628417daa36ca391083dc13): perf score=1.000000
I20260812 06:18:26.683957  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: MajorDeltaCompactionOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.175s	user 0.123s	sys 0.049s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28836135,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":176,"lbm_read_time_us":13623,"lbm_reads_lt_1ms":664,"lbm_write_time_us":34290,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":3000}
I20260812 06:18:26.684716  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13): perf score=14.095187
I20260812 06:18:26.746042  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.061s	user 0.038s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23382,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:26.746593  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13): perf score=3.181125
I20260812 06:18:26.759708  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.013s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":5052,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:26.760211  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13): perf score=2.188937
I20260812 06:18:26.771028  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4110,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:26.771881  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling MajorDeltaCompactionOp(3e71bc732628417daa36ca391083dc13): perf score=1.000000
I20260812 06:18:26.949638  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: MajorDeltaCompactionOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.178s	user 0.123s	sys 0.054s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28836244,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":776,"lbm_read_time_us":12453,"lbm_reads_lt_1ms":673,"lbm_write_time_us":35953,"lbm_writes_lt_1ms":643,"mutex_wait_us":298,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":3000}
I20260812 06:18:26.950268  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13): perf score=14.095187
I20260812 06:18:27.002593  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.052s	user 0.033s	sys 0.017s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22492,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:27.003171  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13): perf score=2.188937
I20260812 06:18:27.025589  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.022s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5570,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:27.026247  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling MajorDeltaCompactionOp(3e71bc732628417daa36ca391083dc13): perf score=1.000000
I20260812 06:18:27.192265  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: MajorDeltaCompactionOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.166s	user 0.113s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":782,"lbm_read_time_us":11704,"lbm_reads_lt_1ms":564,"lbm_write_time_us":31956,"lbm_writes_lt_1ms":543,"mutex_wait_us":71,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":16896,"update_count":2500}
I20260812 06:18:27.193264  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13): perf score=14.095187
I20260812 06:18:27.247766  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.054s	user 0.032s	sys 0.017s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23135,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:27.248396  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling MajorDeltaCompactionOp(3e71bc732628417daa36ca391083dc13): perf score=1.000000
I20260812 06:18:27.413725  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: MajorDeltaCompactionOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.165s	user 0.124s	sys 0.035s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20631194,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":954,"lbm_read_time_us":9293,"lbm_reads_lt_1ms":463,"lbm_write_time_us":26538,"lbm_writes_lt_1ms":443,"mutex_wait_us":301,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6400,"update_count":2000}
I20260812 06:18:27.414572  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13): perf score=14.095187
I20260812 06:18:27.471902  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.057s	user 0.027s	sys 0.022s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":22915,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:27.472532  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13): perf score=2.188937
I20260812 06:18:27.486423  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.014s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5223,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:27.486997  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling FlushMRSOp(3e71bc732628417daa36ca391083dc13): perf score=1.000000
I20260812 06:18:27.522588  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: FlushMRSOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.035s	user 0.026s	sys 0.000s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":87,"dirs.run_cpu_time_us":308,"dirs.run_wall_time_us":1940,"drs_written":1,"lbm_read_time_us":45,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1870,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:27.523386  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling LogGCOp(3e71bc732628417daa36ca391083dc13): free 115490353 bytes of WAL
I20260812 06:18:27.523639  9604 log_reader.cc:385] T 3e71bc732628417daa36ca391083dc13: removed 11 log segments from log reader
I20260812 06:18:27.523716  9604 log.cc:1079] T 3e71bc732628417daa36ca391083dc13 P 0b3e9d4cdb694b268a1d442980d26b4e: Deleting log segment in path: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502517496-9483-0/minicluster-data/ts-0-root/wals/3e71bc732628417daa36ca391083dc13/wal-000000026 (ops 127-131)
I20260812 06:18:27.523777  9604 log.cc:1079] T 3e71bc732628417daa36ca391083dc13 P 0b3e9d4cdb694b268a1d442980d26b4e: Deleting log segment in path: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502517496-9483-0/minicluster-data/ts-0-root/wals/3e71bc732628417daa36ca391083dc13/wal-000000027 (ops 132-136)
I20260812 06:18:27.523840  9604 log.cc:1079] T 3e71bc732628417daa36ca391083dc13 P 0b3e9d4cdb694b268a1d442980d26b4e: Deleting log segment in path: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502517496-9483-0/minicluster-data/ts-0-root/wals/3e71bc732628417daa36ca391083dc13/wal-000000028 (ops 137-141)
I20260812 06:18:27.523886  9604 log.cc:1079] T 3e71bc732628417daa36ca391083dc13 P 0b3e9d4cdb694b268a1d442980d26b4e: Deleting log segment in path: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502517496-9483-0/minicluster-data/ts-0-root/wals/3e71bc732628417daa36ca391083dc13/wal-000000029 (ops 142-146)
I20260812 06:18:27.523922  9604 log.cc:1079] T 3e71bc732628417daa36ca391083dc13 P 0b3e9d4cdb694b268a1d442980d26b4e: Deleting log segment in path: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502517496-9483-0/minicluster-data/ts-0-root/wals/3e71bc732628417daa36ca391083dc13/wal-000000030 (ops 147-151)
I20260812 06:18:27.523960  9604 log.cc:1079] T 3e71bc732628417daa36ca391083dc13 P 0b3e9d4cdb694b268a1d442980d26b4e: Deleting log segment in path: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502517496-9483-0/minicluster-data/ts-0-root/wals/3e71bc732628417daa36ca391083dc13/wal-000000031 (ops 152-156)
I20260812 06:18:27.523994  9604 log.cc:1079] T 3e71bc732628417daa36ca391083dc13 P 0b3e9d4cdb694b268a1d442980d26b4e: Deleting log segment in path: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502517496-9483-0/minicluster-data/ts-0-root/wals/3e71bc732628417daa36ca391083dc13/wal-000000032 (ops 157-161)
I20260812 06:18:27.524031  9604 log.cc:1079] T 3e71bc732628417daa36ca391083dc13 P 0b3e9d4cdb694b268a1d442980d26b4e: Deleting log segment in path: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502517496-9483-0/minicluster-data/ts-0-root/wals/3e71bc732628417daa36ca391083dc13/wal-000000033 (ops 162-166)
I20260812 06:18:27.524068  9604 log.cc:1079] T 3e71bc732628417daa36ca391083dc13 P 0b3e9d4cdb694b268a1d442980d26b4e: Deleting log segment in path: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502517496-9483-0/minicluster-data/ts-0-root/wals/3e71bc732628417daa36ca391083dc13/wal-000000034 (ops 167-171)
I20260812 06:18:27.524112  9604 log.cc:1079] T 3e71bc732628417daa36ca391083dc13 P 0b3e9d4cdb694b268a1d442980d26b4e: Deleting log segment in path: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502517496-9483-0/minicluster-data/ts-0-root/wals/3e71bc732628417daa36ca391083dc13/wal-000000035 (ops 172-176)
I20260812 06:18:27.524155  9604 log.cc:1079] T 3e71bc732628417daa36ca391083dc13 P 0b3e9d4cdb694b268a1d442980d26b4e: Deleting log segment in path: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502517496-9483-0/minicluster-data/ts-0-root/wals/3e71bc732628417daa36ca391083dc13/wal-000000036 (ops 177-180)
I20260812 06:18:27.551636  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: LogGCOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.028s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:18:27.552270  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling UndoDeltaBlockGCOp(3e71bc732628417daa36ca391083dc13): 447 bytes on disk
I20260812 06:18:27.552829  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: UndoDeltaBlockGCOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4}
I20260812 06:18:27.553777  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13): perf score=3.181125
I20260812 06:18:27.575963  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.022s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4740,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:27.576519  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13): perf score=2.188937
I20260812 06:18:27.586876  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3799,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:27.587430  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling MajorDeltaCompactionOp(3e71bc732628417daa36ca391083dc13): perf score=1.000000
I20260812 06:18:27.829118  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: MajorDeltaCompactionOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.241s	user 0.162s	sys 0.068s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32938776,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1526,"lbm_read_time_us":15272,"lbm_reads_lt_1ms":774,"lbm_write_time_us":39662,"lbm_writes_lt_1ms":743,"mutex_wait_us":39,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":96256,"thread_start_us":104,"threads_started":1,"update_count":3500}
I20260812 06:18:27.830065  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13): perf score=18.063937
I20260812 06:18:27.901489  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.071s	user 0.046s	sys 0.017s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":28534,"lbm_writes_lt_1ms":503,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2500}
I20260812 06:18:27.902060  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13): perf score=2.188937
I20260812 06:18:27.913447  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: FlushDeltaMemStoresOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.011s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4256,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:27.914031  9675 maintenance_manager.cc:419] P 0b3e9d4cdb694b268a1d442980d26b4e: Scheduling MajorDeltaCompactionOp(3e71bc732628417daa36ca391083dc13): perf score=1.000000
I20260812 06:18:28.007187  9483 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.180s	user 1.874s	sys 0.169s
I20260812 06:18:28.079279  9483 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.071s	user 0.002s	sys 0.000s
I20260812 06:18:28.080026  9483 tablet_server.cc:179] TabletServer@127.9.66.193:0 shutting down...
I20260812 06:18:28.100876  9604 maintenance_manager.cc:643] P 0b3e9d4cdb694b268a1d442980d26b4e: MajorDeltaCompactionOp(3e71bc732628417daa36ca391083dc13) complete. Timing: real 0.187s	user 0.109s	sys 0.076s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28836137,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1095,"lbm_read_time_us":14537,"lbm_reads_lt_1ms":668,"lbm_write_time_us":32405,"lbm_writes_lt_1ms":643,"mutex_wait_us":202,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":19712,"update_count":3000}
I20260812 06:18:28.101779  9483 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:28.102267  9483 tablet_replica.cc:333] T 3e71bc732628417daa36ca391083dc13 P 0b3e9d4cdb694b268a1d442980d26b4e: stopping tablet replica
I20260812 06:18:28.102524  9483 raft_consensus.cc:2243] T 3e71bc732628417daa36ca391083dc13 P 0b3e9d4cdb694b268a1d442980d26b4e [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:28.102803  9483 raft_consensus.cc:2272] T 3e71bc732628417daa36ca391083dc13 P 0b3e9d4cdb694b268a1d442980d26b4e [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:28.132349  9483 tablet_server.cc:196] TabletServer@127.9.66.193:0 shutdown complete.
I20260812 06:18:28.155748  9483 master.cc:562] Master@127.9.66.254:34393 shutting down...
I20260812 06:18:28.160100  9483 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 5ddcb540004b4072921f4fa14eb5c9a3 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:28.160354  9483 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 5ddcb540004b4072921f4fa14eb5c9a3 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:28.160449  9483 tablet_replica.cc:333] T 00000000000000000000000000000000 P 5ddcb540004b4072921f4fa14eb5c9a3: stopping tablet replica
I20260812 06:18:28.173472  9483 master.cc:584] Master@127.9.66.254:34393 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5741 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:28.271401  9483 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.9.66.254:38927
I20260812 06:18:28.271858  9483 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:28.274916  9716 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:28.274971  9483 server_base.cc:1061] running on GCE node
W20260812 06:18:28.274878  9718 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:28.274902  9715 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:28.275379  9483 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:28.275435  9483 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:28.275457  9483 hybrid_clock.cc:648] HybridClock initialized: now 1786515508275457 us; error 0 us; skew 500 ppm
I20260812 06:18:28.276503  9483 webserver.cc:533] Webserver started at http://127.9.66.254:34255/ using document root <none> and password file <none>
I20260812 06:18:28.276733  9483 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:28.276784  9483 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:28.276851  9483 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:28.277447  9483 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502517496-9483-0/minicluster-data/master-0-root/instance:
uuid: "3d965f5e0f6d4e8c9ea501f0f92f198a"
format_stamp: "Formatted at 2026-08-12 06:18:28 on dist-test-slave-vxj2"
I20260812 06:18:28.279456  9483 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:28.280722  9725 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:28.281126  9483 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:28.281349  9483 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502517496-9483-0/minicluster-data/master-0-root
uuid: "3d965f5e0f6d4e8c9ea501f0f92f198a"
format_stamp: "Formatted at 2026-08-12 06:18:28 on dist-test-slave-vxj2"
I20260812 06:18:28.281454  9483 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502517496-9483-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502517496-9483-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502517496-9483-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:28.291596  9483 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:28.292089  9483 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:28.296836  9483 rpc_server.cc:307] RPC server started. Bound to: 127.9.66.254:38927
I20260812 06:18:28.298924  9790 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.9.66.254:38927 every 8 connection(s)
I20260812 06:18:28.301216  9791 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:28.307744  9791 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 3d965f5e0f6d4e8c9ea501f0f92f198a: Bootstrap starting.
I20260812 06:18:28.308594  9791 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 3d965f5e0f6d4e8c9ea501f0f92f198a: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:28.309938  9791 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 3d965f5e0f6d4e8c9ea501f0f92f198a: No bootstrap required, opened a new log
I20260812 06:18:28.310353  9791 raft_consensus.cc:359] T 00000000000000000000000000000000 P 3d965f5e0f6d4e8c9ea501f0f92f198a [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3d965f5e0f6d4e8c9ea501f0f92f198a" member_type: VOTER }
I20260812 06:18:28.310447  9791 raft_consensus.cc:385] T 00000000000000000000000000000000 P 3d965f5e0f6d4e8c9ea501f0f92f198a [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:28.310472  9791 raft_consensus.cc:740] T 00000000000000000000000000000000 P 3d965f5e0f6d4e8c9ea501f0f92f198a [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 3d965f5e0f6d4e8c9ea501f0f92f198a, State: Initialized, Role: FOLLOWER
I20260812 06:18:28.310606  9791 consensus_queue.cc:260] T 00000000000000000000000000000000 P 3d965f5e0f6d4e8c9ea501f0f92f198a [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: "3d965f5e0f6d4e8c9ea501f0f92f198a" member_type: VOTER }
I20260812 06:18:28.310670  9791 raft_consensus.cc:399] T 00000000000000000000000000000000 P 3d965f5e0f6d4e8c9ea501f0f92f198a [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:28.310693  9791 raft_consensus.cc:493] T 00000000000000000000000000000000 P 3d965f5e0f6d4e8c9ea501f0f92f198a [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:28.310729  9791 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 3d965f5e0f6d4e8c9ea501f0f92f198a [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:28.311501  9791 raft_consensus.cc:515] T 00000000000000000000000000000000 P 3d965f5e0f6d4e8c9ea501f0f92f198a [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3d965f5e0f6d4e8c9ea501f0f92f198a" member_type: VOTER }
I20260812 06:18:28.311632  9791 leader_election.cc:304] T 00000000000000000000000000000000 P 3d965f5e0f6d4e8c9ea501f0f92f198a [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: 3d965f5e0f6d4e8c9ea501f0f92f198a; no voters: 
I20260812 06:18:28.311827  9791 leader_election.cc:290] T 00000000000000000000000000000000 P 3d965f5e0f6d4e8c9ea501f0f92f198a [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:28.312047  9796 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 3d965f5e0f6d4e8c9ea501f0f92f198a [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:28.312297  9796 raft_consensus.cc:697] T 00000000000000000000000000000000 P 3d965f5e0f6d4e8c9ea501f0f92f198a [term 1 LEADER]: Becoming Leader. State: Replica: 3d965f5e0f6d4e8c9ea501f0f92f198a, State: Running, Role: LEADER
I20260812 06:18:28.312374  9791 sys_catalog.cc:565] T 00000000000000000000000000000000 P 3d965f5e0f6d4e8c9ea501f0f92f198a [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:28.312503  9796 consensus_queue.cc:237] T 00000000000000000000000000000000 P 3d965f5e0f6d4e8c9ea501f0f92f198a [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: "3d965f5e0f6d4e8c9ea501f0f92f198a" member_type: VOTER }
I20260812 06:18:28.313026  9798 sys_catalog.cc:455] T 00000000000000000000000000000000 P 3d965f5e0f6d4e8c9ea501f0f92f198a [sys.catalog]: SysCatalogTable state changed. Reason: New leader 3d965f5e0f6d4e8c9ea501f0f92f198a. Latest consensus state: current_term: 1 leader_uuid: "3d965f5e0f6d4e8c9ea501f0f92f198a" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3d965f5e0f6d4e8c9ea501f0f92f198a" member_type: VOTER } }
I20260812 06:18:28.313010  9797 sys_catalog.cc:455] T 00000000000000000000000000000000 P 3d965f5e0f6d4e8c9ea501f0f92f198a [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "3d965f5e0f6d4e8c9ea501f0f92f198a" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3d965f5e0f6d4e8c9ea501f0f92f198a" member_type: VOTER } }
I20260812 06:18:28.313143  9798 sys_catalog.cc:458] T 00000000000000000000000000000000 P 3d965f5e0f6d4e8c9ea501f0f92f198a [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:28.313177  9797 sys_catalog.cc:458] T 00000000000000000000000000000000 P 3d965f5e0f6d4e8c9ea501f0f92f198a [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:28.313542  9803 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:28.314412  9803 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:28.314653  9483 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:28.316625  9803 catalog_manager.cc:1383] Generated new cluster ID: bda76aa26f04458ca765bacd207ae45d
I20260812 06:18:28.316685  9803 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:28.336162  9803 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:28.336864  9803 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:28.341621  9803 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 3d965f5e0f6d4e8c9ea501f0f92f198a: Generated new TSK 0
I20260812 06:18:28.341885  9803 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:28.347325  9483 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:28.349855  9815 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:28.349990  9816 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:28.350073  9483 server_base.cc:1061] running on GCE node
W20260812 06:18:28.349994  9818 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:28.350370  9483 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:28.350415  9483 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:28.350432  9483 hybrid_clock.cc:648] HybridClock initialized: now 1786515508350432 us; error 0 us; skew 500 ppm
I20260812 06:18:28.351400  9483 webserver.cc:533] Webserver started at http://127.9.66.193:37701/ using document root <none> and password file <none>
I20260812 06:18:28.351601  9483 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:28.351662  9483 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:28.351743  9483 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:28.352198  9483 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502517496-9483-0/minicluster-data/ts-0-root/instance:
uuid: "6c51a820b5de47e59c8213e7ebf44192"
format_stamp: "Formatted at 2026-08-12 06:18:28 on dist-test-slave-vxj2"
I20260812 06:18:28.353984  9483 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:28.355199  9824 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:28.355549  9483 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:28.355623  9483 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502517496-9483-0/minicluster-data/ts-0-root
uuid: "6c51a820b5de47e59c8213e7ebf44192"
format_stamp: "Formatted at 2026-08-12 06:18:28 on dist-test-slave-vxj2"
I20260812 06:18:28.355731  9483 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502517496-9483-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502517496-9483-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502517496-9483-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:28.377074  9483 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:28.377636  9483 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:28.378028  9483 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:28.378552  9483 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:28.378686  9483 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:28.378820  9483 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:28.378850  9483 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:28.385143  9483 rpc_server.cc:307] RPC server started. Bound to: 127.9.66.193:42405
I20260812 06:18:28.385685  9903 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.9.66.193:42405 every 8 connection(s)
I20260812 06:18:28.393169  9904 heartbeater.cc:344] Connected to a master server at 127.9.66.254:38927
I20260812 06:18:28.393352  9904 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:28.393719  9904 heartbeater.cc:507] Master 127.9.66.254:38927 requested a full tablet report, sending...
I20260812 06:18:28.394714  9747 ts_manager.cc:194] Registered new tserver with Master: 6c51a820b5de47e59c8213e7ebf44192 (127.9.66.193:42405)
I20260812 06:18:28.396059  9747 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:47472
I20260812 06:18:28.396433  9483 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.010465179s
I20260812 06:18:28.408506  9747 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:47476:
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:28.420147  9853 tablet_service.cc:1511] Processing CreateTablet for tablet 09ea8f043789443f9b302244cd57b15e (DEFAULT_TABLE table=heavy-update-compaction-test [id=23ef70c5bfad48639b5d2d45e60f7849]), partition=
I20260812 06:18:28.420513  9853 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 09ea8f043789443f9b302244cd57b15e. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:28.423273  9918 tablet_bootstrap.cc:492] T 09ea8f043789443f9b302244cd57b15e P 6c51a820b5de47e59c8213e7ebf44192: Bootstrap starting.
I20260812 06:18:28.424382  9918 tablet_bootstrap.cc:654] T 09ea8f043789443f9b302244cd57b15e P 6c51a820b5de47e59c8213e7ebf44192: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:28.425880  9918 tablet_bootstrap.cc:492] T 09ea8f043789443f9b302244cd57b15e P 6c51a820b5de47e59c8213e7ebf44192: No bootstrap required, opened a new log
I20260812 06:18:28.425973  9918 ts_tablet_manager.cc:1403] T 09ea8f043789443f9b302244cd57b15e P 6c51a820b5de47e59c8213e7ebf44192: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:18:28.426402  9918 raft_consensus.cc:359] T 09ea8f043789443f9b302244cd57b15e P 6c51a820b5de47e59c8213e7ebf44192 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6c51a820b5de47e59c8213e7ebf44192" member_type: VOTER last_known_addr { host: "127.9.66.193" port: 42405 } }
I20260812 06:18:28.426517  9918 raft_consensus.cc:385] T 09ea8f043789443f9b302244cd57b15e P 6c51a820b5de47e59c8213e7ebf44192 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:28.426544  9918 raft_consensus.cc:740] T 09ea8f043789443f9b302244cd57b15e P 6c51a820b5de47e59c8213e7ebf44192 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 6c51a820b5de47e59c8213e7ebf44192, State: Initialized, Role: FOLLOWER
I20260812 06:18:28.426700  9918 consensus_queue.cc:260] T 09ea8f043789443f9b302244cd57b15e P 6c51a820b5de47e59c8213e7ebf44192 [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: "6c51a820b5de47e59c8213e7ebf44192" member_type: VOTER last_known_addr { host: "127.9.66.193" port: 42405 } }
I20260812 06:18:28.426805  9918 raft_consensus.cc:399] T 09ea8f043789443f9b302244cd57b15e P 6c51a820b5de47e59c8213e7ebf44192 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:28.426851  9918 raft_consensus.cc:493] T 09ea8f043789443f9b302244cd57b15e P 6c51a820b5de47e59c8213e7ebf44192 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:28.426890  9918 raft_consensus.cc:3060] T 09ea8f043789443f9b302244cd57b15e P 6c51a820b5de47e59c8213e7ebf44192 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:28.427696  9918 raft_consensus.cc:515] T 09ea8f043789443f9b302244cd57b15e P 6c51a820b5de47e59c8213e7ebf44192 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6c51a820b5de47e59c8213e7ebf44192" member_type: VOTER last_known_addr { host: "127.9.66.193" port: 42405 } }
I20260812 06:18:28.427832  9918 leader_election.cc:304] T 09ea8f043789443f9b302244cd57b15e P 6c51a820b5de47e59c8213e7ebf44192 [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: 6c51a820b5de47e59c8213e7ebf44192; no voters: 
I20260812 06:18:28.428009  9918 leader_election.cc:290] T 09ea8f043789443f9b302244cd57b15e P 6c51a820b5de47e59c8213e7ebf44192 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:28.428171  9920 raft_consensus.cc:2804] T 09ea8f043789443f9b302244cd57b15e P 6c51a820b5de47e59c8213e7ebf44192 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:28.428368  9918 ts_tablet_manager.cc:1434] T 09ea8f043789443f9b302244cd57b15e P 6c51a820b5de47e59c8213e7ebf44192: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:18:28.428436  9920 raft_consensus.cc:697] T 09ea8f043789443f9b302244cd57b15e P 6c51a820b5de47e59c8213e7ebf44192 [term 1 LEADER]: Becoming Leader. State: Replica: 6c51a820b5de47e59c8213e7ebf44192, State: Running, Role: LEADER
I20260812 06:18:28.428393  9904 heartbeater.cc:499] Master 127.9.66.254:38927 was elected leader, sending a full tablet report...
I20260812 06:18:28.428695  9920 consensus_queue.cc:237] T 09ea8f043789443f9b302244cd57b15e P 6c51a820b5de47e59c8213e7ebf44192 [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: "6c51a820b5de47e59c8213e7ebf44192" member_type: VOTER last_known_addr { host: "127.9.66.193" port: 42405 } }
I20260812 06:18:28.430236  9747 catalog_manager.cc:5719] T 09ea8f043789443f9b302244cd57b15e P 6c51a820b5de47e59c8213e7ebf44192 reported cstate change: term changed from 0 to 1, leader changed from <none> to 6c51a820b5de47e59c8213e7ebf44192 (127.9.66.193). New cstate: current_term: 1 leader_uuid: "6c51a820b5de47e59c8213e7ebf44192" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6c51a820b5de47e59c8213e7ebf44192" member_type: VOTER last_known_addr { host: "127.9.66.193" port: 42405 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:28.491506  9483 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.056s	user 0.013s	sys 0.010s
I20260812 06:18:28.636606  9906 maintenance_manager.cc:419] P 6c51a820b5de47e59c8213e7ebf44192: Scheduling FlushMRSOp(09ea8f043789443f9b302244cd57b15e): perf score=16.078378
I20260812 06:18:28.805485  9830 maintenance_manager.cc:643] P 6c51a820b5de47e59c8213e7ebf44192: FlushMRSOp(09ea8f043789443f9b302244cd57b15e) complete. Timing: real 0.168s	user 0.115s	sys 0.050s Metrics: {"bytes_written":9681945,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":120,"dirs.run_cpu_time_us":258,"dirs.run_wall_time_us":1141,"drs_written":1,"lbm_read_time_us":71,"lbm_reads_lt_1ms":4,"lbm_write_time_us":41250,"lbm_writes_lt_1ms":693,"mutex_wait_us":256,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":16512,"update_count":1180}
I20260812 06:18:28.806216  9906 maintenance_manager.cc:419] P 6c51a820b5de47e59c8213e7ebf44192: Scheduling LogGCOp(09ea8f043789443f9b302244cd57b15e): free 20743880 bytes of WAL
I20260812 06:18:28.806499  9830 log_reader.cc:385] T 09ea8f043789443f9b302244cd57b15e: removed 2 log segments from log reader
I20260812 06:18:28.806545  9830 log.cc:1079] T 09ea8f043789443f9b302244cd57b15e P 6c51a820b5de47e59c8213e7ebf44192: Deleting log segment in path: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502517496-9483-0/minicluster-data/ts-0-root/wals/09ea8f043789443f9b302244cd57b15e/wal-000000001 (ops 1-6)
I20260812 06:18:28.806578  9830 log.cc:1079] T 09ea8f043789443f9b302244cd57b15e P 6c51a820b5de47e59c8213e7ebf44192: Deleting log segment in path: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502517496-9483-0/minicluster-data/ts-0-root/wals/09ea8f043789443f9b302244cd57b15e/wal-000000002 (ops 7-11)
I20260812 06:18:28.811939  9830 maintenance_manager.cc:643] P 6c51a820b5de47e59c8213e7ebf44192: LogGCOp(09ea8f043789443f9b302244cd57b15e) complete. Timing: real 0.006s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:18:28.812459  9906 maintenance_manager.cc:419] P 6c51a820b5de47e59c8213e7ebf44192: Scheduling UndoDeltaBlockGCOp(09ea8f043789443f9b302244cd57b15e): 16411393 bytes on disk
I20260812 06:18:28.813253  9830 maintenance_manager.cc:643] P 6c51a820b5de47e59c8213e7ebf44192: UndoDeltaBlockGCOp(09ea8f043789443f9b302244cd57b15e) complete. Timing: real 0.001s	user 0.001s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":211,"lbm_reads_lt_1ms":4}
I20260812 06:18:28.813802  9906 maintenance_manager.cc:419] P 6c51a820b5de47e59c8213e7ebf44192: Scheduling FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e): perf score=1.196750
I20260812 06:18:28.824663  9830 maintenance_manager.cc:643] P 6c51a820b5de47e59c8213e7ebf44192: FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":2625754,"delete_count":0,"lbm_write_time_us":3586,"lbm_writes_lt_1ms":67,"reinsert_count":0,"update_count":320}
I20260812 06:18:28.825385  9906 maintenance_manager.cc:419] P 6c51a820b5de47e59c8213e7ebf44192: Scheduling MajorDeltaCompactionOp(09ea8f043789443f9b302244cd57b15e): perf score=1.000000
I20260812 06:18:28.954885  9830 maintenance_manager.cc:643] P 6c51a820b5de47e59c8213e7ebf44192: MajorDeltaCompactionOp(09ea8f043789443f9b302244cd57b15e) complete. Timing: real 0.129s	user 0.092s	sys 0.037s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16569827,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":575,"lbm_read_time_us":10401,"lbm_reads_lt_1ms":364,"lbm_write_time_us":20032,"lbm_writes_lt_1ms":343,"mutex_wait_us":25,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":6400,"thread_start_us":356,"threads_started":5,"update_count":1500}
I20260812 06:18:28.955660  9906 maintenance_manager.cc:419] P 6c51a820b5de47e59c8213e7ebf44192: Scheduling FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e): perf score=10.126437
I20260812 06:18:29.005635  9830 maintenance_manager.cc:643] P 6c51a820b5de47e59c8213e7ebf44192: FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e) complete. Timing: real 0.050s	user 0.026s	sys 0.011s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":16112,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:29.006150  9906 maintenance_manager.cc:419] P 6c51a820b5de47e59c8213e7ebf44192: Scheduling FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e): perf score=2.188937
I20260812 06:18:29.017390  9830 maintenance_manager.cc:643] P 6c51a820b5de47e59c8213e7ebf44192: FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4182,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:29.018036  9906 maintenance_manager.cc:419] P 6c51a820b5de47e59c8213e7ebf44192: Scheduling MajorDeltaCompactionOp(09ea8f043789443f9b302244cd57b15e): perf score=1.000000
I20260812 06:18:29.169808  9830 maintenance_manager.cc:643] P 6c51a820b5de47e59c8213e7ebf44192: MajorDeltaCompactionOp(09ea8f043789443f9b302244cd57b15e) complete. Timing: real 0.152s	user 0.107s	sys 0.041s 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":1352,"lbm_read_time_us":10283,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25606,"lbm_writes_lt_1ms":443,"mutex_wait_us":299,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":45568,"update_count":2000}
I20260812 06:18:29.170579  9906 maintenance_manager.cc:419] P 6c51a820b5de47e59c8213e7ebf44192: Scheduling FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e): perf score=10.126437
I20260812 06:18:29.209791  9830 maintenance_manager.cc:643] P 6c51a820b5de47e59c8213e7ebf44192: FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e) complete. Timing: real 0.039s	user 0.034s	sys 0.005s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16693,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:29.210326  9906 maintenance_manager.cc:419] P 6c51a820b5de47e59c8213e7ebf44192: Scheduling FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e): perf score=2.188937
I20260812 06:18:29.222970  9830 maintenance_manager.cc:643] P 6c51a820b5de47e59c8213e7ebf44192: FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4274,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:29.223491  9906 maintenance_manager.cc:419] P 6c51a820b5de47e59c8213e7ebf44192: Scheduling MajorDeltaCompactionOp(09ea8f043789443f9b302244cd57b15e): perf score=1.000000
I20260812 06:18:29.356850  9830 maintenance_manager.cc:643] P 6c51a820b5de47e59c8213e7ebf44192: MajorDeltaCompactionOp(09ea8f043789443f9b302244cd57b15e) complete. Timing: real 0.133s	user 0.103s	sys 0.029s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1608,"lbm_read_time_us":8058,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27057,"lbm_writes_lt_1ms":443,"mutex_wait_us":327,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":17664,"update_count":2000}
I20260812 06:18:29.357653  9906 maintenance_manager.cc:419] P 6c51a820b5de47e59c8213e7ebf44192: Scheduling FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e): perf score=10.126437
I20260812 06:18:29.405527  9830 maintenance_manager.cc:643] P 6c51a820b5de47e59c8213e7ebf44192: FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e) complete. Timing: real 0.048s	user 0.024s	sys 0.023s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":20781,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:29.406136  9906 maintenance_manager.cc:419] P 6c51a820b5de47e59c8213e7ebf44192: Scheduling FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e): perf score=2.188937
I20260812 06:18:29.419663  9830 maintenance_manager.cc:643] P 6c51a820b5de47e59c8213e7ebf44192: FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e) complete. Timing: real 0.013s	user 0.010s	sys 0.001s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4589,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:29.420204  9906 maintenance_manager.cc:419] P 6c51a820b5de47e59c8213e7ebf44192: Scheduling MajorDeltaCompactionOp(09ea8f043789443f9b302244cd57b15e): perf score=1.000000
I20260812 06:18:29.552090  9830 maintenance_manager.cc:643] P 6c51a820b5de47e59c8213e7ebf44192: MajorDeltaCompactionOp(09ea8f043789443f9b302244cd57b15e) complete. Timing: real 0.132s	user 0.098s	sys 0.033s 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":753,"lbm_read_time_us":8645,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26809,"lbm_writes_lt_1ms":443,"mutex_wait_us":35,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:29.552618  9906 maintenance_manager.cc:419] P 6c51a820b5de47e59c8213e7ebf44192: Scheduling FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e): perf score=10.126437
I20260812 06:18:29.604650  9830 maintenance_manager.cc:643] P 6c51a820b5de47e59c8213e7ebf44192: FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e) complete. Timing: real 0.052s	user 0.028s	sys 0.014s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16284,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:29.605307  9906 maintenance_manager.cc:419] P 6c51a820b5de47e59c8213e7ebf44192: Scheduling FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e): perf score=2.188937
I20260812 06:18:29.616998  9830 maintenance_manager.cc:643] P 6c51a820b5de47e59c8213e7ebf44192: FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4475,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:29.617682  9906 maintenance_manager.cc:419] P 6c51a820b5de47e59c8213e7ebf44192: Scheduling MajorDeltaCompactionOp(09ea8f043789443f9b302244cd57b15e): perf score=1.000000
I20260812 06:18:29.780476  9830 maintenance_manager.cc:643] P 6c51a820b5de47e59c8213e7ebf44192: MajorDeltaCompactionOp(09ea8f043789443f9b302244cd57b15e) complete. Timing: real 0.163s	user 0.111s	sys 0.051s 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":496,"lbm_read_time_us":12164,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24939,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12032,"update_count":2000}
I20260812 06:18:29.781095  9906 maintenance_manager.cc:419] P 6c51a820b5de47e59c8213e7ebf44192: Scheduling FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e): perf score=10.126437
I20260812 06:18:29.829445  9830 maintenance_manager.cc:643] P 6c51a820b5de47e59c8213e7ebf44192: FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e) complete. Timing: real 0.048s	user 0.026s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16918,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:29.829995  9906 maintenance_manager.cc:419] P 6c51a820b5de47e59c8213e7ebf44192: Scheduling FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e): perf score=2.188937
I20260812 06:18:29.841471  9830 maintenance_manager.cc:643] P 6c51a820b5de47e59c8213e7ebf44192: FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e) complete. Timing: real 0.011s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4195,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:29.842247  9906 maintenance_manager.cc:419] P 6c51a820b5de47e59c8213e7ebf44192: Scheduling MajorDeltaCompactionOp(09ea8f043789443f9b302244cd57b15e): perf score=1.000000
I20260812 06:18:29.977360  9830 maintenance_manager.cc:643] P 6c51a820b5de47e59c8213e7ebf44192: MajorDeltaCompactionOp(09ea8f043789443f9b302244cd57b15e) complete. Timing: real 0.135s	user 0.113s	sys 0.020s 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":404,"lbm_read_time_us":9553,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24972,"lbm_writes_lt_1ms":443,"mutex_wait_us":36,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7936,"update_count":2000}
I20260812 06:18:29.978410  9906 maintenance_manager.cc:419] P 6c51a820b5de47e59c8213e7ebf44192: Scheduling FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e): perf score=10.126437
I20260812 06:18:30.020264  9830 maintenance_manager.cc:643] P 6c51a820b5de47e59c8213e7ebf44192: FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e) complete. Timing: real 0.041s	user 0.016s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16742,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:30.020861  9906 maintenance_manager.cc:419] P 6c51a820b5de47e59c8213e7ebf44192: Scheduling FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e): perf score=2.188937
I20260812 06:18:30.032620  9830 maintenance_manager.cc:643] P 6c51a820b5de47e59c8213e7ebf44192: FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e) complete. Timing: real 0.012s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4578,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:30.033505  9906 maintenance_manager.cc:419] P 6c51a820b5de47e59c8213e7ebf44192: Scheduling MajorDeltaCompactionOp(09ea8f043789443f9b302244cd57b15e): perf score=1.000000
I20260812 06:18:30.175881  9830 maintenance_manager.cc:643] P 6c51a820b5de47e59c8213e7ebf44192: MajorDeltaCompactionOp(09ea8f043789443f9b302244cd57b15e) complete. Timing: real 0.142s	user 0.109s	sys 0.029s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":747,"lbm_read_time_us":9169,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29691,"lbm_writes_lt_1ms":443,"mutex_wait_us":43,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:18:30.176754  9906 maintenance_manager.cc:419] P 6c51a820b5de47e59c8213e7ebf44192: Scheduling FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e): perf score=10.126437
I20260812 06:18:30.234748  9830 maintenance_manager.cc:643] P 6c51a820b5de47e59c8213e7ebf44192: FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e) complete. Timing: real 0.058s	user 0.026s	sys 0.019s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17081,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:30.235430  9906 maintenance_manager.cc:419] P 6c51a820b5de47e59c8213e7ebf44192: Scheduling FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e): perf score=2.188937
I20260812 06:18:30.247004  9830 maintenance_manager.cc:643] P 6c51a820b5de47e59c8213e7ebf44192: FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4345,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:30.247578  9906 maintenance_manager.cc:419] P 6c51a820b5de47e59c8213e7ebf44192: Scheduling FlushMRSOp(09ea8f043789443f9b302244cd57b15e): perf score=1.000000
I20260812 06:18:30.290158  9830 maintenance_manager.cc:643] P 6c51a820b5de47e59c8213e7ebf44192: FlushMRSOp(09ea8f043789443f9b302244cd57b15e) complete. Timing: real 0.042s	user 0.029s	sys 0.005s Metrics: {"bytes_written":1275443,"cfile_init":1,"dirs.queue_time_us":91,"dirs.run_cpu_time_us":345,"dirs.run_wall_time_us":1761,"drs_written":1,"lbm_read_time_us":44,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1606,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:30.291087  9906 maintenance_manager.cc:419] P 6c51a820b5de47e59c8213e7ebf44192: Scheduling LogGCOp(09ea8f043789443f9b302244cd57b15e): free 124257245 bytes of WAL
I20260812 06:18:30.291335  9830 log_reader.cc:385] T 09ea8f043789443f9b302244cd57b15e: removed 12 log segments from log reader
I20260812 06:18:30.291381  9830 log.cc:1079] T 09ea8f043789443f9b302244cd57b15e P 6c51a820b5de47e59c8213e7ebf44192: Deleting log segment in path: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502517496-9483-0/minicluster-data/ts-0-root/wals/09ea8f043789443f9b302244cd57b15e/wal-000000003 (ops 12-16)
I20260812 06:18:30.291440  9830 log.cc:1079] T 09ea8f043789443f9b302244cd57b15e P 6c51a820b5de47e59c8213e7ebf44192: Deleting log segment in path: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502517496-9483-0/minicluster-data/ts-0-root/wals/09ea8f043789443f9b302244cd57b15e/wal-000000004 (ops 17-21)
I20260812 06:18:30.291496  9830 log.cc:1079] T 09ea8f043789443f9b302244cd57b15e P 6c51a820b5de47e59c8213e7ebf44192: Deleting log segment in path: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502517496-9483-0/minicluster-data/ts-0-root/wals/09ea8f043789443f9b302244cd57b15e/wal-000000005 (ops 22-26)
I20260812 06:18:30.291558  9830 log.cc:1079] T 09ea8f043789443f9b302244cd57b15e P 6c51a820b5de47e59c8213e7ebf44192: Deleting log segment in path: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502517496-9483-0/minicluster-data/ts-0-root/wals/09ea8f043789443f9b302244cd57b15e/wal-000000006 (ops 27-31)
I20260812 06:18:30.291607  9830 log.cc:1079] T 09ea8f043789443f9b302244cd57b15e P 6c51a820b5de47e59c8213e7ebf44192: Deleting log segment in path: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502517496-9483-0/minicluster-data/ts-0-root/wals/09ea8f043789443f9b302244cd57b15e/wal-000000007 (ops 32-36)
I20260812 06:18:30.291656  9830 log.cc:1079] T 09ea8f043789443f9b302244cd57b15e P 6c51a820b5de47e59c8213e7ebf44192: Deleting log segment in path: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502517496-9483-0/minicluster-data/ts-0-root/wals/09ea8f043789443f9b302244cd57b15e/wal-000000008 (ops 37-40)
I20260812 06:18:30.291718  9830 log.cc:1079] T 09ea8f043789443f9b302244cd57b15e P 6c51a820b5de47e59c8213e7ebf44192: Deleting log segment in path: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502517496-9483-0/minicluster-data/ts-0-root/wals/09ea8f043789443f9b302244cd57b15e/wal-000000009 (ops 41-45)
I20260812 06:18:30.291764  9830 log.cc:1079] T 09ea8f043789443f9b302244cd57b15e P 6c51a820b5de47e59c8213e7ebf44192: Deleting log segment in path: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502517496-9483-0/minicluster-data/ts-0-root/wals/09ea8f043789443f9b302244cd57b15e/wal-000000010 (ops 46-50)
I20260812 06:18:30.291805  9830 log.cc:1079] T 09ea8f043789443f9b302244cd57b15e P 6c51a820b5de47e59c8213e7ebf44192: Deleting log segment in path: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502517496-9483-0/minicluster-data/ts-0-root/wals/09ea8f043789443f9b302244cd57b15e/wal-000000011 (ops 51-55)
I20260812 06:18:30.291846  9830 log.cc:1079] T 09ea8f043789443f9b302244cd57b15e P 6c51a820b5de47e59c8213e7ebf44192: Deleting log segment in path: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502517496-9483-0/minicluster-data/ts-0-root/wals/09ea8f043789443f9b302244cd57b15e/wal-000000012 (ops 56-60)
I20260812 06:18:30.291890  9830 log.cc:1079] T 09ea8f043789443f9b302244cd57b15e P 6c51a820b5de47e59c8213e7ebf44192: Deleting log segment in path: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502517496-9483-0/minicluster-data/ts-0-root/wals/09ea8f043789443f9b302244cd57b15e/wal-000000013 (ops 61-65)
I20260812 06:18:30.291934  9830 log.cc:1079] T 09ea8f043789443f9b302244cd57b15e P 6c51a820b5de47e59c8213e7ebf44192: Deleting log segment in path: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502517496-9483-0/minicluster-data/ts-0-root/wals/09ea8f043789443f9b302244cd57b15e/wal-000000014 (ops 66-70)
I20260812 06:18:30.323071  9830 maintenance_manager.cc:643] P 6c51a820b5de47e59c8213e7ebf44192: LogGCOp(09ea8f043789443f9b302244cd57b15e) complete. Timing: real 0.032s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:18:30.323542  9906 maintenance_manager.cc:419] P 6c51a820b5de47e59c8213e7ebf44192: Scheduling UndoDeltaBlockGCOp(09ea8f043789443f9b302244cd57b15e): 482 bytes on disk
I20260812 06:18:30.323999  9830 maintenance_manager.cc:643] P 6c51a820b5de47e59c8213e7ebf44192: UndoDeltaBlockGCOp(09ea8f043789443f9b302244cd57b15e) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4}
I20260812 06:18:30.324616  9906 maintenance_manager.cc:419] P 6c51a820b5de47e59c8213e7ebf44192: Scheduling FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e): perf score=3.181125
I20260812 06:18:30.339871  9830 maintenance_manager.cc:643] P 6c51a820b5de47e59c8213e7ebf44192: FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e) complete. Timing: real 0.015s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":4453,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:30.340337  9906 maintenance_manager.cc:419] P 6c51a820b5de47e59c8213e7ebf44192: Scheduling FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e): perf score=2.188937
I20260812 06:18:30.350692  9830 maintenance_manager.cc:643] P 6c51a820b5de47e59c8213e7ebf44192: FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3692,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:30.351352  9906 maintenance_manager.cc:419] P 6c51a820b5de47e59c8213e7ebf44192: Scheduling MajorDeltaCompactionOp(09ea8f043789443f9b302244cd57b15e): perf score=1.000000
I20260812 06:18:30.570194  9830 maintenance_manager.cc:643] P 6c51a820b5de47e59c8213e7ebf44192: MajorDeltaCompactionOp(09ea8f043789443f9b302244cd57b15e) complete. Timing: real 0.219s	user 0.137s	sys 0.080s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877329,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":2553,"lbm_read_time_us":14122,"lbm_reads_lt_1ms":674,"lbm_write_time_us":36210,"lbm_writes_lt_1ms":643,"mutex_wait_us":874,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":6400,"thread_start_us":107,"threads_started":1,"update_count":3000}
I20260812 06:18:30.571162  9906 maintenance_manager.cc:419] P 6c51a820b5de47e59c8213e7ebf44192: Scheduling FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e): perf score=14.095187
I20260812 06:18:30.629695  9830 maintenance_manager.cc:643] P 6c51a820b5de47e59c8213e7ebf44192: FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e) complete. Timing: real 0.058s	user 0.033s	sys 0.017s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22504,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:30.630434  9906 maintenance_manager.cc:419] P 6c51a820b5de47e59c8213e7ebf44192: Scheduling FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e): perf score=2.188937
I20260812 06:18:30.646695  9830 maintenance_manager.cc:643] P 6c51a820b5de47e59c8213e7ebf44192: FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e) complete. Timing: real 0.016s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5909,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:30.647346  9906 maintenance_manager.cc:419] P 6c51a820b5de47e59c8213e7ebf44192: Scheduling MajorDeltaCompactionOp(09ea8f043789443f9b302244cd57b15e): perf score=1.000000
I20260812 06:18:30.843988  9830 maintenance_manager.cc:643] P 6c51a820b5de47e59c8213e7ebf44192: MajorDeltaCompactionOp(09ea8f043789443f9b302244cd57b15e) complete. Timing: real 0.196s	user 0.112s	sys 0.080s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":789,"lbm_read_time_us":13576,"lbm_reads_lt_1ms":564,"lbm_write_time_us":32897,"lbm_writes_lt_1ms":543,"mutex_wait_us":73,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":18944,"update_count":2500}
I20260812 06:18:30.844725  9906 maintenance_manager.cc:419] P 6c51a820b5de47e59c8213e7ebf44192: Scheduling FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e): perf score=14.095187
I20260812 06:18:30.900184  9830 maintenance_manager.cc:643] P 6c51a820b5de47e59c8213e7ebf44192: FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e) complete. Timing: real 0.055s	user 0.028s	sys 0.023s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":26401,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:30.900758  9906 maintenance_manager.cc:419] P 6c51a820b5de47e59c8213e7ebf44192: Scheduling FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e): perf score=2.188937
I20260812 06:18:30.915025  9830 maintenance_manager.cc:643] P 6c51a820b5de47e59c8213e7ebf44192: FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e) complete. Timing: real 0.014s	user 0.003s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4994,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:30.915634  9906 maintenance_manager.cc:419] P 6c51a820b5de47e59c8213e7ebf44192: Scheduling MajorDeltaCompactionOp(09ea8f043789443f9b302244cd57b15e): perf score=1.000000
I20260812 06:18:31.102321  9830 maintenance_manager.cc:643] P 6c51a820b5de47e59c8213e7ebf44192: MajorDeltaCompactionOp(09ea8f043789443f9b302244cd57b15e) complete. Timing: real 0.186s	user 0.135s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":271,"lbm_read_time_us":11307,"lbm_reads_lt_1ms":564,"lbm_write_time_us":32688,"lbm_writes_lt_1ms":543,"mutex_wait_us":49,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":17920,"update_count":2500}
I20260812 06:18:31.102984  9906 maintenance_manager.cc:419] P 6c51a820b5de47e59c8213e7ebf44192: Scheduling FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e): perf score=14.095187
I20260812 06:18:31.165691  9830 maintenance_manager.cc:643] P 6c51a820b5de47e59c8213e7ebf44192: FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e) complete. Timing: real 0.063s	user 0.037s	sys 0.022s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":20927,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:31.166366  9906 maintenance_manager.cc:419] P 6c51a820b5de47e59c8213e7ebf44192: Scheduling FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e): perf score=2.188937
I20260812 06:18:31.177860  9830 maintenance_manager.cc:643] P 6c51a820b5de47e59c8213e7ebf44192: FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e) complete. Timing: real 0.011s	user 0.010s	sys 0.000s 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:31.178453  9906 maintenance_manager.cc:419] P 6c51a820b5de47e59c8213e7ebf44192: Scheduling MajorDeltaCompactionOp(09ea8f043789443f9b302244cd57b15e): perf score=1.000000
I20260812 06:18:31.391357  9830 maintenance_manager.cc:643] P 6c51a820b5de47e59c8213e7ebf44192: MajorDeltaCompactionOp(09ea8f043789443f9b302244cd57b15e) complete. Timing: real 0.213s	user 0.128s	sys 0.068s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":567,"lbm_read_time_us":14135,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31425,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:31.392123  9906 maintenance_manager.cc:419] P 6c51a820b5de47e59c8213e7ebf44192: Scheduling FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e): perf score=14.095187
I20260812 06:18:31.453500  9830 maintenance_manager.cc:643] P 6c51a820b5de47e59c8213e7ebf44192: FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e) complete. Timing: real 0.061s	user 0.041s	sys 0.019s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":26616,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:31.454106  9906 maintenance_manager.cc:419] P 6c51a820b5de47e59c8213e7ebf44192: Scheduling FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e): perf score=2.188937
I20260812 06:18:31.474045  9830 maintenance_manager.cc:643] P 6c51a820b5de47e59c8213e7ebf44192: FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e) complete. Timing: real 0.020s	user 0.006s	sys 0.012s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":7108,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:31.474812  9906 maintenance_manager.cc:419] P 6c51a820b5de47e59c8213e7ebf44192: Scheduling MajorDeltaCompactionOp(09ea8f043789443f9b302244cd57b15e): perf score=1.000000
I20260812 06:18:31.666682  9830 maintenance_manager.cc:643] P 6c51a820b5de47e59c8213e7ebf44192: MajorDeltaCompactionOp(09ea8f043789443f9b302244cd57b15e) complete. Timing: real 0.192s	user 0.128s	sys 0.063s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774686,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":743,"lbm_read_time_us":12552,"lbm_reads_lt_1ms":564,"lbm_write_time_us":31805,"lbm_writes_lt_1ms":543,"mutex_wait_us":343,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5248,"update_count":2500}
I20260812 06:18:31.667559  9906 maintenance_manager.cc:419] P 6c51a820b5de47e59c8213e7ebf44192: Scheduling FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e): perf score=14.095187
I20260812 06:18:31.723647  9830 maintenance_manager.cc:643] P 6c51a820b5de47e59c8213e7ebf44192: FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e) complete. Timing: real 0.056s	user 0.037s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25539,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:31.724642  9906 maintenance_manager.cc:419] P 6c51a820b5de47e59c8213e7ebf44192: Scheduling FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e): perf score=2.188937
I20260812 06:18:31.745291  9830 maintenance_manager.cc:643] P 6c51a820b5de47e59c8213e7ebf44192: FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e) complete. Timing: real 0.020s	user 0.013s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6377,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:31.745839  9906 maintenance_manager.cc:419] P 6c51a820b5de47e59c8213e7ebf44192: Scheduling FlushMRSOp(09ea8f043789443f9b302244cd57b15e): perf score=1.000000
I20260812 06:18:31.794533  9830 maintenance_manager.cc:643] P 6c51a820b5de47e59c8213e7ebf44192: FlushMRSOp(09ea8f043789443f9b302244cd57b15e) complete. Timing: real 0.049s	user 0.033s	sys 0.003s Metrics: {"bytes_written":1152514,"cfile_init":1,"dirs.queue_time_us":99,"dirs.run_cpu_time_us":297,"dirs.run_wall_time_us":1655,"drs_written":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2427,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:31.795260  9906 maintenance_manager.cc:419] P 6c51a820b5de47e59c8213e7ebf44192: Scheduling LogGCOp(09ea8f043789443f9b302244cd57b15e): free 108988505 bytes of WAL
I20260812 06:18:31.795500  9830 log_reader.cc:385] T 09ea8f043789443f9b302244cd57b15e: removed 11 log segments from log reader
I20260812 06:18:31.795567  9830 log.cc:1079] T 09ea8f043789443f9b302244cd57b15e P 6c51a820b5de47e59c8213e7ebf44192: Deleting log segment in path: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502517496-9483-0/minicluster-data/ts-0-root/wals/09ea8f043789443f9b302244cd57b15e/wal-000000015 (ops 71-75)
I20260812 06:18:31.795626  9830 log.cc:1079] T 09ea8f043789443f9b302244cd57b15e P 6c51a820b5de47e59c8213e7ebf44192: Deleting log segment in path: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502517496-9483-0/minicluster-data/ts-0-root/wals/09ea8f043789443f9b302244cd57b15e/wal-000000016 (ops 76-80)
I20260812 06:18:31.795667  9830 log.cc:1079] T 09ea8f043789443f9b302244cd57b15e P 6c51a820b5de47e59c8213e7ebf44192: Deleting log segment in path: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502517496-9483-0/minicluster-data/ts-0-root/wals/09ea8f043789443f9b302244cd57b15e/wal-000000017 (ops 81-85)
I20260812 06:18:31.795706  9830 log.cc:1079] T 09ea8f043789443f9b302244cd57b15e P 6c51a820b5de47e59c8213e7ebf44192: Deleting log segment in path: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502517496-9483-0/minicluster-data/ts-0-root/wals/09ea8f043789443f9b302244cd57b15e/wal-000000018 (ops 86-90)
I20260812 06:18:31.795742  9830 log.cc:1079] T 09ea8f043789443f9b302244cd57b15e P 6c51a820b5de47e59c8213e7ebf44192: Deleting log segment in path: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502517496-9483-0/minicluster-data/ts-0-root/wals/09ea8f043789443f9b302244cd57b15e/wal-000000019 (ops 91-95)
I20260812 06:18:31.795792  9830 log.cc:1079] T 09ea8f043789443f9b302244cd57b15e P 6c51a820b5de47e59c8213e7ebf44192: Deleting log segment in path: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502517496-9483-0/minicluster-data/ts-0-root/wals/09ea8f043789443f9b302244cd57b15e/wal-000000020 (ops 96-100)
I20260812 06:18:31.795833  9830 log.cc:1079] T 09ea8f043789443f9b302244cd57b15e P 6c51a820b5de47e59c8213e7ebf44192: Deleting log segment in path: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502517496-9483-0/minicluster-data/ts-0-root/wals/09ea8f043789443f9b302244cd57b15e/wal-000000021 (ops 101-104)
I20260812 06:18:31.795873  9830 log.cc:1079] T 09ea8f043789443f9b302244cd57b15e P 6c51a820b5de47e59c8213e7ebf44192: Deleting log segment in path: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502517496-9483-0/minicluster-data/ts-0-root/wals/09ea8f043789443f9b302244cd57b15e/wal-000000022 (ops 105-109)
I20260812 06:18:31.795913  9830 log.cc:1079] T 09ea8f043789443f9b302244cd57b15e P 6c51a820b5de47e59c8213e7ebf44192: Deleting log segment in path: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502517496-9483-0/minicluster-data/ts-0-root/wals/09ea8f043789443f9b302244cd57b15e/wal-000000023 (ops 110-114)
I20260812 06:18:31.795953  9830 log.cc:1079] T 09ea8f043789443f9b302244cd57b15e P 6c51a820b5de47e59c8213e7ebf44192: Deleting log segment in path: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502517496-9483-0/minicluster-data/ts-0-root/wals/09ea8f043789443f9b302244cd57b15e/wal-000000024 (ops 115-119)
I20260812 06:18:31.795991  9830 log.cc:1079] T 09ea8f043789443f9b302244cd57b15e P 6c51a820b5de47e59c8213e7ebf44192: Deleting log segment in path: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502517496-9483-0/minicluster-data/ts-0-root/wals/09ea8f043789443f9b302244cd57b15e/wal-000000025 (ops 120-124)
I20260812 06:18:31.824489  9830 maintenance_manager.cc:643] P 6c51a820b5de47e59c8213e7ebf44192: LogGCOp(09ea8f043789443f9b302244cd57b15e) complete. Timing: real 0.029s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:18:31.824955  9906 maintenance_manager.cc:419] P 6c51a820b5de47e59c8213e7ebf44192: Scheduling FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e): perf score=6.157687
I20260812 06:18:31.846864  9830 maintenance_manager.cc:643] P 6c51a820b5de47e59c8213e7ebf44192: FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e) complete. Timing: real 0.022s	user 0.015s	sys 0.005s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":9006,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:18:31.847400  9906 maintenance_manager.cc:419] P 6c51a820b5de47e59c8213e7ebf44192: Scheduling LogGCOp(09ea8f043789443f9b302244cd57b15e): free 11564877 bytes of WAL
I20260812 06:18:31.847632  9830 log_reader.cc:385] T 09ea8f043789443f9b302244cd57b15e: removed 1 log segments from log reader
I20260812 06:18:31.847675  9830 log.cc:1079] T 09ea8f043789443f9b302244cd57b15e P 6c51a820b5de47e59c8213e7ebf44192: Deleting log segment in path: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502517496-9483-0/minicluster-data/ts-0-root/wals/09ea8f043789443f9b302244cd57b15e/wal-000000026 (ops 125-128)
I20260812 06:18:31.850497  9830 maintenance_manager.cc:643] P 6c51a820b5de47e59c8213e7ebf44192: LogGCOp(09ea8f043789443f9b302244cd57b15e) complete. Timing: real 0.003s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:18:31.850977  9906 maintenance_manager.cc:419] P 6c51a820b5de47e59c8213e7ebf44192: Scheduling UndoDeltaBlockGCOp(09ea8f043789443f9b302244cd57b15e): 448 bytes on disk
I20260812 06:18:31.851677  9830 maintenance_manager.cc:643] P 6c51a820b5de47e59c8213e7ebf44192: UndoDeltaBlockGCOp(09ea8f043789443f9b302244cd57b15e) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":110,"lbm_reads_lt_1ms":4}
I20260812 06:18:31.852324  9906 maintenance_manager.cc:419] P 6c51a820b5de47e59c8213e7ebf44192: Scheduling MajorDeltaCompactionOp(09ea8f043789443f9b302244cd57b15e): perf score=1.000000
I20260812 06:18:32.115399  9830 maintenance_manager.cc:643] P 6c51a820b5de47e59c8213e7ebf44192: MajorDeltaCompactionOp(09ea8f043789443f9b302244cd57b15e) complete. Timing: real 0.263s	user 0.171s	sys 0.084s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":32979632,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":2246,"lbm_read_time_us":17655,"lbm_reads_lt_1ms":769,"lbm_write_time_us":43472,"lbm_writes_lt_1ms":743,"mutex_wait_us":936,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":21376,"thread_start_us":88,"threads_started":1,"update_count":3500}
I20260812 06:18:32.116137  9906 maintenance_manager.cc:419] P 6c51a820b5de47e59c8213e7ebf44192: Scheduling FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e): perf score=18.063937
I20260812 06:18:32.202661  9830 maintenance_manager.cc:643] P 6c51a820b5de47e59c8213e7ebf44192: FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e) complete. Timing: real 0.086s	user 0.047s	sys 0.024s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":32444,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:32.203346  9906 maintenance_manager.cc:419] P 6c51a820b5de47e59c8213e7ebf44192: Scheduling FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e): perf score=2.188937
I20260812 06:18:32.217748  9830 maintenance_manager.cc:643] P 6c51a820b5de47e59c8213e7ebf44192: FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e) complete. Timing: real 0.014s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5004,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:32.218441  9906 maintenance_manager.cc:419] P 6c51a820b5de47e59c8213e7ebf44192: Scheduling MajorDeltaCompactionOp(09ea8f043789443f9b302244cd57b15e): perf score=1.000000
I20260812 06:18:32.420104  9830 maintenance_manager.cc:643] P 6c51a820b5de47e59c8213e7ebf44192: MajorDeltaCompactionOp(09ea8f043789443f9b302244cd57b15e) complete. Timing: real 0.201s	user 0.132s	sys 0.066s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877103,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":469,"lbm_read_time_us":12061,"lbm_reads_lt_1ms":668,"lbm_write_time_us":35002,"lbm_writes_lt_1ms":643,"mutex_wait_us":1,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":4480,"update_count":3000}
I20260812 06:18:32.420836  9906 maintenance_manager.cc:419] P 6c51a820b5de47e59c8213e7ebf44192: Scheduling FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e): perf score=14.095187
I20260812 06:18:32.467469  9830 maintenance_manager.cc:643] P 6c51a820b5de47e59c8213e7ebf44192: FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e) complete. Timing: real 0.046s	user 0.033s	sys 0.011s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20274,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:32.468423  9906 maintenance_manager.cc:419] P 6c51a820b5de47e59c8213e7ebf44192: Scheduling FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e): perf score=2.188937
I20260812 06:18:32.496783  9830 maintenance_manager.cc:643] P 6c51a820b5de47e59c8213e7ebf44192: FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e) complete. Timing: real 0.028s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6198,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:32.497421  9906 maintenance_manager.cc:419] P 6c51a820b5de47e59c8213e7ebf44192: Scheduling FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e): perf score=2.188937
I20260812 06:18:32.508828  9830 maintenance_manager.cc:643] P 6c51a820b5de47e59c8213e7ebf44192: FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4271,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:32.509574  9906 maintenance_manager.cc:419] P 6c51a820b5de47e59c8213e7ebf44192: Scheduling MajorDeltaCompactionOp(09ea8f043789443f9b302244cd57b15e): perf score=1.000000
I20260812 06:18:32.732584  9830 maintenance_manager.cc:643] P 6c51a820b5de47e59c8213e7ebf44192: MajorDeltaCompactionOp(09ea8f043789443f9b302244cd57b15e) complete. Timing: real 0.223s	user 0.145s	sys 0.077s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877221,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":896,"lbm_read_time_us":15738,"lbm_reads_lt_1ms":673,"lbm_write_time_us":37533,"lbm_writes_lt_1ms":643,"mutex_wait_us":347,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":7680,"update_count":3000}
I20260812 06:18:32.733328  9906 maintenance_manager.cc:419] P 6c51a820b5de47e59c8213e7ebf44192: Scheduling FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e): perf score=14.095187
I20260812 06:18:32.786755  9830 maintenance_manager.cc:643] P 6c51a820b5de47e59c8213e7ebf44192: FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e) complete. Timing: real 0.053s	user 0.034s	sys 0.017s Metrics: {"bytes_written":16532976,"delete_count":0,"lbm_write_time_us":22654,"lbm_writes_lt_1ms":406,"mutex_wait_us":476,"reinsert_count":0,"update_count":2015}
I20260812 06:18:32.787709  9906 maintenance_manager.cc:419] P 6c51a820b5de47e59c8213e7ebf44192: Scheduling FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e): perf score=2.188937
I20260812 06:18:32.803536  9830 maintenance_manager.cc:643] P 6c51a820b5de47e59c8213e7ebf44192: FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e) complete. Timing: real 0.016s	user 0.001s	sys 0.012s Metrics: {"bytes_written":3979584,"delete_count":0,"lbm_write_time_us":6122,"lbm_writes_lt_1ms":100,"reinsert_count":0,"update_count":485}
I20260812 06:18:32.804041  9906 maintenance_manager.cc:419] P 6c51a820b5de47e59c8213e7ebf44192: Scheduling MajorDeltaCompactionOp(09ea8f043789443f9b302244cd57b15e): perf score=1.000000
I20260812 06:18:32.982116  9830 maintenance_manager.cc:643] P 6c51a820b5de47e59c8213e7ebf44192: MajorDeltaCompactionOp(09ea8f043789443f9b302244cd57b15e) complete. Timing: real 0.178s	user 0.130s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":825,"lbm_read_time_us":11315,"lbm_reads_lt_1ms":564,"lbm_write_time_us":31792,"lbm_writes_lt_1ms":543,"mutex_wait_us":21,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14208,"update_count":2500}
I20260812 06:18:32.983111  9906 maintenance_manager.cc:419] P 6c51a820b5de47e59c8213e7ebf44192: Scheduling FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e): perf score=14.095187
I20260812 06:18:33.036610  9830 maintenance_manager.cc:643] P 6c51a820b5de47e59c8213e7ebf44192: FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e) complete. Timing: real 0.053s	user 0.033s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23466,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:33.037304  9906 maintenance_manager.cc:419] P 6c51a820b5de47e59c8213e7ebf44192: Scheduling FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e): perf score=2.188937
I20260812 06:18:33.053694  9830 maintenance_manager.cc:643] P 6c51a820b5de47e59c8213e7ebf44192: FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e) complete. Timing: real 0.016s	user 0.011s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6369,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:33.054221  9906 maintenance_manager.cc:419] P 6c51a820b5de47e59c8213e7ebf44192: Scheduling MajorDeltaCompactionOp(09ea8f043789443f9b302244cd57b15e): perf score=1.000000
I20260812 06:18:33.231513  9830 maintenance_manager.cc:643] P 6c51a820b5de47e59c8213e7ebf44192: MajorDeltaCompactionOp(09ea8f043789443f9b302244cd57b15e) complete. Timing: real 0.177s	user 0.125s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":115,"lbm_read_time_us":11877,"lbm_reads_lt_1ms":568,"lbm_write_time_us":29286,"lbm_writes_lt_1ms":543,"mutex_wait_us":34,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5120,"update_count":2500}
I20260812 06:18:33.232120  9906 maintenance_manager.cc:419] P 6c51a820b5de47e59c8213e7ebf44192: Scheduling FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e): perf score=15.087375
I20260812 06:18:33.297312  9830 maintenance_manager.cc:643] P 6c51a820b5de47e59c8213e7ebf44192: FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e) complete. Timing: real 0.065s	user 0.034s	sys 0.031s Metrics: {"bytes_written":16738094,"delete_count":0,"lbm_write_time_us":24049,"lbm_writes_lt_1ms":411,"reinsert_count":0,"update_count":2040}
I20260812 06:18:33.297972  9906 maintenance_manager.cc:419] P 6c51a820b5de47e59c8213e7ebf44192: Scheduling FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e): perf score=2.188937
I20260812 06:18:33.313007  9830 maintenance_manager.cc:643] P 6c51a820b5de47e59c8213e7ebf44192: FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e) complete. Timing: real 0.015s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3774459,"delete_count":0,"lbm_write_time_us":3958,"lbm_writes_lt_1ms":95,"reinsert_count":0,"update_count":460}
I20260812 06:18:33.313689  9906 maintenance_manager.cc:419] P 6c51a820b5de47e59c8213e7ebf44192: Scheduling FlushMRSOp(09ea8f043789443f9b302244cd57b15e): perf score=1.000000
I20260812 06:18:33.357939  9830 maintenance_manager.cc:643] P 6c51a820b5de47e59c8213e7ebf44192: FlushMRSOp(09ea8f043789443f9b302244cd57b15e) complete. Timing: real 0.044s	user 0.021s	sys 0.009s Metrics: {"bytes_written":1193505,"cfile_init":1,"dirs.queue_time_us":141,"dirs.run_cpu_time_us":381,"dirs.run_wall_time_us":1951,"drs_written":1,"lbm_read_time_us":90,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2300,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:33.359112  9906 maintenance_manager.cc:419] P 6c51a820b5de47e59c8213e7ebf44192: Scheduling FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e): perf score=3.181125
I20260812 06:18:33.378546  9830 maintenance_manager.cc:643] P 6c51a820b5de47e59c8213e7ebf44192: FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e) complete. Timing: real 0.019s	user 0.006s	sys 0.006s Metrics: {"bytes_written":4471879,"delete_count":0,"lbm_write_time_us":5040,"lbm_writes_lt_1ms":112,"reinsert_count":0,"update_count":545}
I20260812 06:18:33.379160  9906 maintenance_manager.cc:419] P 6c51a820b5de47e59c8213e7ebf44192: Scheduling LogGCOp(09ea8f043789443f9b302244cd57b15e): free 121006654 bytes of WAL
I20260812 06:18:33.379491  9830 log_reader.cc:385] T 09ea8f043789443f9b302244cd57b15e: removed 12 log segments from log reader
I20260812 06:18:33.379537  9830 log.cc:1079] T 09ea8f043789443f9b302244cd57b15e P 6c51a820b5de47e59c8213e7ebf44192: Deleting log segment in path: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502517496-9483-0/minicluster-data/ts-0-root/wals/09ea8f043789443f9b302244cd57b15e/wal-000000027 (ops 129-133)
I20260812 06:18:33.379571  9830 log.cc:1079] T 09ea8f043789443f9b302244cd57b15e P 6c51a820b5de47e59c8213e7ebf44192: Deleting log segment in path: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502517496-9483-0/minicluster-data/ts-0-root/wals/09ea8f043789443f9b302244cd57b15e/wal-000000028 (ops 134-138)
I20260812 06:18:33.379642  9830 log.cc:1079] T 09ea8f043789443f9b302244cd57b15e P 6c51a820b5de47e59c8213e7ebf44192: Deleting log segment in path: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502517496-9483-0/minicluster-data/ts-0-root/wals/09ea8f043789443f9b302244cd57b15e/wal-000000029 (ops 139-143)
I20260812 06:18:33.379693  9830 log.cc:1079] T 09ea8f043789443f9b302244cd57b15e P 6c51a820b5de47e59c8213e7ebf44192: Deleting log segment in path: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502517496-9483-0/minicluster-data/ts-0-root/wals/09ea8f043789443f9b302244cd57b15e/wal-000000030 (ops 144-148)
I20260812 06:18:33.379742  9830 log.cc:1079] T 09ea8f043789443f9b302244cd57b15e P 6c51a820b5de47e59c8213e7ebf44192: Deleting log segment in path: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502517496-9483-0/minicluster-data/ts-0-root/wals/09ea8f043789443f9b302244cd57b15e/wal-000000031 (ops 149-153)
I20260812 06:18:33.379794  9830 log.cc:1079] T 09ea8f043789443f9b302244cd57b15e P 6c51a820b5de47e59c8213e7ebf44192: Deleting log segment in path: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502517496-9483-0/minicluster-data/ts-0-root/wals/09ea8f043789443f9b302244cd57b15e/wal-000000032 (ops 154-158)
I20260812 06:18:33.379848  9830 log.cc:1079] T 09ea8f043789443f9b302244cd57b15e P 6c51a820b5de47e59c8213e7ebf44192: Deleting log segment in path: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502517496-9483-0/minicluster-data/ts-0-root/wals/09ea8f043789443f9b302244cd57b15e/wal-000000033 (ops 159-163)
I20260812 06:18:33.379891  9830 log.cc:1079] T 09ea8f043789443f9b302244cd57b15e P 6c51a820b5de47e59c8213e7ebf44192: Deleting log segment in path: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502517496-9483-0/minicluster-data/ts-0-root/wals/09ea8f043789443f9b302244cd57b15e/wal-000000034 (ops 164-168)
I20260812 06:18:33.379936  9830 log.cc:1079] T 09ea8f043789443f9b302244cd57b15e P 6c51a820b5de47e59c8213e7ebf44192: Deleting log segment in path: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502517496-9483-0/minicluster-data/ts-0-root/wals/09ea8f043789443f9b302244cd57b15e/wal-000000035 (ops 169-173)
I20260812 06:18:33.379979  9830 log.cc:1079] T 09ea8f043789443f9b302244cd57b15e P 6c51a820b5de47e59c8213e7ebf44192: Deleting log segment in path: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502517496-9483-0/minicluster-data/ts-0-root/wals/09ea8f043789443f9b302244cd57b15e/wal-000000036 (ops 174-178)
I20260812 06:18:33.380019  9830 log.cc:1079] T 09ea8f043789443f9b302244cd57b15e P 6c51a820b5de47e59c8213e7ebf44192: Deleting log segment in path: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502517496-9483-0/minicluster-data/ts-0-root/wals/09ea8f043789443f9b302244cd57b15e/wal-000000037 (ops 179-182)
I20260812 06:18:33.380054  9830 log.cc:1079] T 09ea8f043789443f9b302244cd57b15e P 6c51a820b5de47e59c8213e7ebf44192: Deleting log segment in path: /tmp/dist-test-taskNKgLFF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502517496-9483-0/minicluster-data/ts-0-root/wals/09ea8f043789443f9b302244cd57b15e/wal-000000038 (ops 183-187)
I20260812 06:18:33.412124  9830 maintenance_manager.cc:643] P 6c51a820b5de47e59c8213e7ebf44192: LogGCOp(09ea8f043789443f9b302244cd57b15e) complete. Timing: real 0.033s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:18:33.412618  9906 maintenance_manager.cc:419] P 6c51a820b5de47e59c8213e7ebf44192: Scheduling UndoDeltaBlockGCOp(09ea8f043789443f9b302244cd57b15e): 462 bytes on disk
I20260812 06:18:33.413120  9830 maintenance_manager.cc:643] P 6c51a820b5de47e59c8213e7ebf44192: UndoDeltaBlockGCOp(09ea8f043789443f9b302244cd57b15e) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4}
I20260812 06:18:33.414007  9906 maintenance_manager.cc:419] P 6c51a820b5de47e59c8213e7ebf44192: Scheduling FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e): perf score=2.188937
I20260812 06:18:33.436546  9830 maintenance_manager.cc:643] P 6c51a820b5de47e59c8213e7ebf44192: FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e) complete. Timing: real 0.022s	user 0.011s	sys 0.004s Metrics: {"bytes_written":3815488,"delete_count":0,"lbm_write_time_us":6679,"lbm_writes_lt_1ms":96,"reinsert_count":0,"update_count":465}
I20260812 06:18:33.437208  9906 maintenance_manager.cc:419] P 6c51a820b5de47e59c8213e7ebf44192: Scheduling FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e): perf score=2.188937
I20260812 06:18:33.450066  9830 maintenance_manager.cc:643] P 6c51a820b5de47e59c8213e7ebf44192: FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e) complete. Timing: real 0.013s	user 0.006s	sys 0.006s Metrics: {"bytes_written":4020609,"delete_count":0,"lbm_write_time_us":4879,"lbm_writes_lt_1ms":101,"reinsert_count":0,"update_count":490}
I20260812 06:18:33.450717  9906 maintenance_manager.cc:419] P 6c51a820b5de47e59c8213e7ebf44192: Scheduling MajorDeltaCompactionOp(09ea8f043789443f9b302244cd57b15e): perf score=1.000000
I20260812 06:18:33.720444  9830 maintenance_manager.cc:643] P 6c51a820b5de47e59c8213e7ebf44192: MajorDeltaCompactionOp(09ea8f043789443f9b302244cd57b15e) complete. Timing: real 0.270s	user 0.179s	sys 0.084s Metrics: {"cfile_cache_miss":835,"cfile_cache_miss_bytes":37082273,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":353,"lbm_read_time_us":19822,"lbm_reads_lt_1ms":875,"lbm_write_time_us":45759,"lbm_writes_lt_1ms":843,"mutex_wait_us":37,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":19968,"thread_start_us":96,"threads_started":1,"update_count":4000}
I20260812 06:18:33.721302  9906 maintenance_manager.cc:419] P 6c51a820b5de47e59c8213e7ebf44192: Scheduling FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e): perf score=18.063937
I20260812 06:18:33.773823  9483 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.282s	user 1.924s	sys 0.192s
I20260812 06:18:33.777400  9830 maintenance_manager.cc:643] P 6c51a820b5de47e59c8213e7ebf44192: FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e) complete. Timing: real 0.056s	user 0.028s	sys 0.025s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":26194,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:33.777930  9906 maintenance_manager.cc:419] P 6c51a820b5de47e59c8213e7ebf44192: Scheduling FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e): perf score=2.188937
I20260812 06:18:33.793604  9830 maintenance_manager.cc:643] P 6c51a820b5de47e59c8213e7ebf44192: FlushDeltaMemStoresOp(09ea8f043789443f9b302244cd57b15e) complete. Timing: real 0.015s	user 0.001s	sys 0.013s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6202,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:33.794267  9906 maintenance_manager.cc:419] P 6c51a820b5de47e59c8213e7ebf44192: Scheduling MajorDeltaCompactionOp(09ea8f043789443f9b302244cd57b15e): perf score=1.000000
I20260812 06:18:33.818284  9483 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.044s	user 0.003s	sys 0.000s
I20260812 06:18:33.818863  9483 tablet_server.cc:179] TabletServer@127.9.66.193:0 shutting down...
I20260812 06:18:33.959685  9830 maintenance_manager.cc:643] P 6c51a820b5de47e59c8213e7ebf44192: MajorDeltaCompactionOp(09ea8f043789443f9b302244cd57b15e) complete. Timing: real 0.165s	user 0.131s	sys 0.031s Metrics: {"cfile_cache_hit":30,"cfile_cache_hit_bytes":4262390,"cfile_cache_miss":602,"cfile_cache_miss_bytes":24614712,"cfile_init":4,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":453,"lbm_read_time_us":12063,"lbm_reads_lt_1ms":618,"lbm_write_time_us":32150,"lbm_writes_lt_1ms":643,"mutex_wait_us":3,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:18:33.960673  9483 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:33.960987  9483 tablet_replica.cc:333] T 09ea8f043789443f9b302244cd57b15e P 6c51a820b5de47e59c8213e7ebf44192: stopping tablet replica
I20260812 06:18:33.961269  9483 raft_consensus.cc:2243] T 09ea8f043789443f9b302244cd57b15e P 6c51a820b5de47e59c8213e7ebf44192 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:33.961495  9483 raft_consensus.cc:2272] T 09ea8f043789443f9b302244cd57b15e P 6c51a820b5de47e59c8213e7ebf44192 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:33.978262  9483 tablet_server.cc:196] TabletServer@127.9.66.193:0 shutdown complete.
I20260812 06:18:34.014030  9483 master.cc:562] Master@127.9.66.254:38927 shutting down...
I20260812 06:18:34.017915  9483 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 3d965f5e0f6d4e8c9ea501f0f92f198a [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:34.018127  9483 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 3d965f5e0f6d4e8c9ea501f0f92f198a [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:34.018185  9483 tablet_replica.cc:333] T 00000000000000000000000000000000 P 3d965f5e0f6d4e8c9ea501f0f92f198a: stopping tablet replica
I20260812 06:18:34.030949  9483 master.cc:584] Master@127.9.66.254:38927 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5854 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11597 ms total)

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