[==========] 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:17:10.945458 30815 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.30.23.254:34873
I20260812 06:17:10.946625 30815 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:17:10.947299 30815 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:17:10.955595 30815 server_base.cc:1061] running on GCE node
W20260812 06:17:10.955508 30822 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:17:10.955508 30823 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:17:10.955894 30826 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:17:10.956933 30815 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:10.957051 30815 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:17:10.957082 30815 hybrid_clock.cc:648] HybridClock initialized: now 1786515430957080 us; error 0 us; skew 500 ppm
I20260812 06:17:10.959398 30815 webserver.cc:533] Webserver started at http://127.30.23.254:44731/ using document root <none> and password file <none>
I20260812 06:17:10.960017 30815 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:10.960088 30815 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:10.960309 30815 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:10.962282 30815 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430933609-30815-0/minicluster-data/master-0-root/instance:
uuid: "e3dfc4ad91b24ebdb68bb20bc800bd79"
format_stamp: "Formatted at 2026-08-12 06:17:10 on dist-test-slave-9jjr"
I20260812 06:17:10.966609 30815 fs_manager.cc:696] Time spent creating directory manager: real 0.004s	user 0.003s	sys 0.000s
I20260812 06:17:10.969137 30833 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:17:10.970539 30815 fs_manager.cc:730] Time spent opening block manager: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:17:10.970715 30815 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430933609-30815-0/minicluster-data/master-0-root
uuid: "e3dfc4ad91b24ebdb68bb20bc800bd79"
format_stamp: "Formatted at 2026-08-12 06:17:10 on dist-test-slave-9jjr"
I20260812 06:17:10.970872 30815 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430933609-30815-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430933609-30815-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430933609-30815-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:17:10.990096 30815 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:10.990911 30815 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:17:10.991124 30815 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:10.999943 30815 rpc_server.cc:307] RPC server started. Bound to: 127.30.23.254:34873
I20260812 06:17:11.000023 30896 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.30.23.254:34873 every 8 connection(s)
I20260812 06:17:11.002620 30897 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:17:11.008733 30897 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P e3dfc4ad91b24ebdb68bb20bc800bd79: Bootstrap starting.
I20260812 06:17:11.011628 30897 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P e3dfc4ad91b24ebdb68bb20bc800bd79: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:11.012838 30897 log.cc:826] T 00000000000000000000000000000000 P e3dfc4ad91b24ebdb68bb20bc800bd79: Log is configured to *not* fsync() on all Append() calls
I20260812 06:17:11.015165 30897 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P e3dfc4ad91b24ebdb68bb20bc800bd79: No bootstrap required, opened a new log
I20260812 06:17:11.018608 30897 raft_consensus.cc:359] T 00000000000000000000000000000000 P e3dfc4ad91b24ebdb68bb20bc800bd79 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e3dfc4ad91b24ebdb68bb20bc800bd79" member_type: VOTER }
I20260812 06:17:11.018833 30897 raft_consensus.cc:385] T 00000000000000000000000000000000 P e3dfc4ad91b24ebdb68bb20bc800bd79 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:11.019054 30897 raft_consensus.cc:740] T 00000000000000000000000000000000 P e3dfc4ad91b24ebdb68bb20bc800bd79 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: e3dfc4ad91b24ebdb68bb20bc800bd79, State: Initialized, Role: FOLLOWER
I20260812 06:17:11.019958 30897 consensus_queue.cc:260] T 00000000000000000000000000000000 P e3dfc4ad91b24ebdb68bb20bc800bd79 [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: "e3dfc4ad91b24ebdb68bb20bc800bd79" member_type: VOTER }
I20260812 06:17:11.020180 30897 raft_consensus.cc:399] T 00000000000000000000000000000000 P e3dfc4ad91b24ebdb68bb20bc800bd79 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:11.020262 30897 raft_consensus.cc:493] T 00000000000000000000000000000000 P e3dfc4ad91b24ebdb68bb20bc800bd79 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:11.020402 30897 raft_consensus.cc:3060] T 00000000000000000000000000000000 P e3dfc4ad91b24ebdb68bb20bc800bd79 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:11.021344 30897 raft_consensus.cc:515] T 00000000000000000000000000000000 P e3dfc4ad91b24ebdb68bb20bc800bd79 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e3dfc4ad91b24ebdb68bb20bc800bd79" member_type: VOTER }
I20260812 06:17:11.021867 30897 leader_election.cc:304] T 00000000000000000000000000000000 P e3dfc4ad91b24ebdb68bb20bc800bd79 [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: e3dfc4ad91b24ebdb68bb20bc800bd79; no voters: 
I20260812 06:17:11.022310 30897 leader_election.cc:290] T 00000000000000000000000000000000 P e3dfc4ad91b24ebdb68bb20bc800bd79 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:11.022535 30901 raft_consensus.cc:2804] T 00000000000000000000000000000000 P e3dfc4ad91b24ebdb68bb20bc800bd79 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:11.022802 30901 raft_consensus.cc:697] T 00000000000000000000000000000000 P e3dfc4ad91b24ebdb68bb20bc800bd79 [term 1 LEADER]: Becoming Leader. State: Replica: e3dfc4ad91b24ebdb68bb20bc800bd79, State: Running, Role: LEADER
I20260812 06:17:11.023303 30901 consensus_queue.cc:237] T 00000000000000000000000000000000 P e3dfc4ad91b24ebdb68bb20bc800bd79 [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: "e3dfc4ad91b24ebdb68bb20bc800bd79" member_type: VOTER }
I20260812 06:17:11.023558 30897 sys_catalog.cc:565] T 00000000000000000000000000000000 P e3dfc4ad91b24ebdb68bb20bc800bd79 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:11.025594 30903 sys_catalog.cc:455] T 00000000000000000000000000000000 P e3dfc4ad91b24ebdb68bb20bc800bd79 [sys.catalog]: SysCatalogTable state changed. Reason: New leader e3dfc4ad91b24ebdb68bb20bc800bd79. Latest consensus state: current_term: 1 leader_uuid: "e3dfc4ad91b24ebdb68bb20bc800bd79" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e3dfc4ad91b24ebdb68bb20bc800bd79" member_type: VOTER } }
I20260812 06:17:11.025768 30903 sys_catalog.cc:458] T 00000000000000000000000000000000 P e3dfc4ad91b24ebdb68bb20bc800bd79 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:11.025580 30902 sys_catalog.cc:455] T 00000000000000000000000000000000 P e3dfc4ad91b24ebdb68bb20bc800bd79 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "e3dfc4ad91b24ebdb68bb20bc800bd79" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e3dfc4ad91b24ebdb68bb20bc800bd79" member_type: VOTER } }
I20260812 06:17:11.026003 30902 sys_catalog.cc:458] T 00000000000000000000000000000000 P e3dfc4ad91b24ebdb68bb20bc800bd79 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:11.026010 30815 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:17:11.028512 30917 catalog_manager.cc:1594] T 00000000000000000000000000000000 P e3dfc4ad91b24ebdb68bb20bc800bd79: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:17:11.028623 30917 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:17:11.028724 30916 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:11.029670 30916 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:11.034998 30916 catalog_manager.cc:1383] Generated new cluster ID: 902651644cdb4eed97c86593277d8007
I20260812 06:17:11.035087 30916 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:11.051971 30916 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:11.053148 30916 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:11.060370 30916 catalog_manager.cc:6092] T 00000000000000000000000000000000 P e3dfc4ad91b24ebdb68bb20bc800bd79: Generated new TSK 0
I20260812 06:17:11.061192 30916 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:11.091192 30815 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:11.094202 30926 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:17:11.094249 30924 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:17:11.094202 30923 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:17:11.094933 30815 server_base.cc:1061] running on GCE node
I20260812 06:17:11.095175 30815 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:11.095227 30815 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:17:11.095250 30815 hybrid_clock.cc:648] HybridClock initialized: now 1786515431095250 us; error 0 us; skew 500 ppm
I20260812 06:17:11.096266 30815 webserver.cc:533] Webserver started at http://127.30.23.193:41661/ using document root <none> and password file <none>
I20260812 06:17:11.096446 30815 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:11.096506 30815 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:11.096596 30815 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:11.097043 30815 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430933609-30815-0/minicluster-data/ts-0-root/instance:
uuid: "011c9100bb6c4a7d9d12071452b77e5e"
format_stamp: "Formatted at 2026-08-12 06:17:11 on dist-test-slave-9jjr"
I20260812 06:17:11.099056 30815 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:11.100222 30931 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:17:11.100569 30815 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:11.100641 30815 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430933609-30815-0/minicluster-data/ts-0-root
uuid: "011c9100bb6c4a7d9d12071452b77e5e"
format_stamp: "Formatted at 2026-08-12 06:17:11 on dist-test-slave-9jjr"
I20260812 06:17:11.100735 30815 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430933609-30815-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430933609-30815-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430933609-30815-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:17:11.107946 30815 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:11.108472 30815 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:11.109052 30815 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:11.109916 30815 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:11.109967 30815 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:11.110036 30815 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:11.110076 30815 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:11.119341 30815 rpc_server.cc:307] RPC server started. Bound to: 127.30.23.193:42299
I20260812 06:17:11.119513 31004 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.30.23.193:42299 every 8 connection(s)
I20260812 06:17:11.131111 31005 heartbeater.cc:344] Connected to a master server at 127.30.23.254:34873
I20260812 06:17:11.131428 31005 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:11.132059 31005 heartbeater.cc:507] Master 127.30.23.254:34873 requested a full tablet report, sending...
I20260812 06:17:11.133961 30854 ts_manager.cc:194] Registered new tserver with Master: 011c9100bb6c4a7d9d12071452b77e5e (127.30.23.193:42299)
I20260812 06:17:11.134032 30815 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.013868327s
I20260812 06:17:11.135622 30854 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:52748
I20260812 06:17:11.145340 30854 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:52760:
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:17:11.161438 30962 tablet_service.cc:1511] Processing CreateTablet for tablet b27206ab2c8841239d010ee8043ecd4b (DEFAULT_TABLE table=heavy-update-compaction-test [id=347d6317a47e437dae9c6981b687178a]), partition=
I20260812 06:17:11.161969 30962 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet b27206ab2c8841239d010ee8043ecd4b. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:11.164600 31024 tablet_bootstrap.cc:492] T b27206ab2c8841239d010ee8043ecd4b P 011c9100bb6c4a7d9d12071452b77e5e: Bootstrap starting.
I20260812 06:17:11.165902 31024 tablet_bootstrap.cc:654] T b27206ab2c8841239d010ee8043ecd4b P 011c9100bb6c4a7d9d12071452b77e5e: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:11.167568 31024 tablet_bootstrap.cc:492] T b27206ab2c8841239d010ee8043ecd4b P 011c9100bb6c4a7d9d12071452b77e5e: No bootstrap required, opened a new log
I20260812 06:17:11.167722 31024 ts_tablet_manager.cc:1403] T b27206ab2c8841239d010ee8043ecd4b P 011c9100bb6c4a7d9d12071452b77e5e: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:17:11.168386 31024 raft_consensus.cc:359] T b27206ab2c8841239d010ee8043ecd4b P 011c9100bb6c4a7d9d12071452b77e5e [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "011c9100bb6c4a7d9d12071452b77e5e" member_type: VOTER last_known_addr { host: "127.30.23.193" port: 42299 } }
I20260812 06:17:11.168535 31024 raft_consensus.cc:385] T b27206ab2c8841239d010ee8043ecd4b P 011c9100bb6c4a7d9d12071452b77e5e [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:11.168572 31024 raft_consensus.cc:740] T b27206ab2c8841239d010ee8043ecd4b P 011c9100bb6c4a7d9d12071452b77e5e [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 011c9100bb6c4a7d9d12071452b77e5e, State: Initialized, Role: FOLLOWER
I20260812 06:17:11.168804 31024 consensus_queue.cc:260] T b27206ab2c8841239d010ee8043ecd4b P 011c9100bb6c4a7d9d12071452b77e5e [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: "011c9100bb6c4a7d9d12071452b77e5e" member_type: VOTER last_known_addr { host: "127.30.23.193" port: 42299 } }
I20260812 06:17:11.168915 31024 raft_consensus.cc:399] T b27206ab2c8841239d010ee8043ecd4b P 011c9100bb6c4a7d9d12071452b77e5e [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:11.169000 31024 raft_consensus.cc:493] T b27206ab2c8841239d010ee8043ecd4b P 011c9100bb6c4a7d9d12071452b77e5e [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:11.169059 31024 raft_consensus.cc:3060] T b27206ab2c8841239d010ee8043ecd4b P 011c9100bb6c4a7d9d12071452b77e5e [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:11.170244 31024 raft_consensus.cc:515] T b27206ab2c8841239d010ee8043ecd4b P 011c9100bb6c4a7d9d12071452b77e5e [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "011c9100bb6c4a7d9d12071452b77e5e" member_type: VOTER last_known_addr { host: "127.30.23.193" port: 42299 } }
I20260812 06:17:11.170413 31024 leader_election.cc:304] T b27206ab2c8841239d010ee8043ecd4b P 011c9100bb6c4a7d9d12071452b77e5e [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: 011c9100bb6c4a7d9d12071452b77e5e; no voters: 
I20260812 06:17:11.170667 31024 leader_election.cc:290] T b27206ab2c8841239d010ee8043ecd4b P 011c9100bb6c4a7d9d12071452b77e5e [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:11.170815 31026 raft_consensus.cc:2804] T b27206ab2c8841239d010ee8043ecd4b P 011c9100bb6c4a7d9d12071452b77e5e [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:11.171051 31024 ts_tablet_manager.cc:1434] T b27206ab2c8841239d010ee8043ecd4b P 011c9100bb6c4a7d9d12071452b77e5e: Time spent starting tablet: real 0.003s	user 0.002s	sys 0.002s
I20260812 06:17:11.171097 31026 raft_consensus.cc:697] T b27206ab2c8841239d010ee8043ecd4b P 011c9100bb6c4a7d9d12071452b77e5e [term 1 LEADER]: Becoming Leader. State: Replica: 011c9100bb6c4a7d9d12071452b77e5e, State: Running, Role: LEADER
I20260812 06:17:11.171326 31005 heartbeater.cc:499] Master 127.30.23.254:34873 was elected leader, sending a full tablet report...
I20260812 06:17:11.171311 31026 consensus_queue.cc:237] T b27206ab2c8841239d010ee8043ecd4b P 011c9100bb6c4a7d9d12071452b77e5e [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: "011c9100bb6c4a7d9d12071452b77e5e" member_type: VOTER last_known_addr { host: "127.30.23.193" port: 42299 } }
I20260812 06:17:11.174508 30854 catalog_manager.cc:5719] T b27206ab2c8841239d010ee8043ecd4b P 011c9100bb6c4a7d9d12071452b77e5e reported cstate change: term changed from 0 to 1, leader changed from <none> to 011c9100bb6c4a7d9d12071452b77e5e (127.30.23.193). New cstate: current_term: 1 leader_uuid: "011c9100bb6c4a7d9d12071452b77e5e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "011c9100bb6c4a7d9d12071452b77e5e" member_type: VOTER last_known_addr { host: "127.30.23.193" port: 42299 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:11.242162 30815 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.059s	user 0.018s	sys 0.008s
I20260812 06:17:11.370777 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling FlushMRSOp(b27206ab2c8841239d010ee8043ecd4b): perf score=15.086190
I20260812 06:17:11.520458 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: FlushMRSOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.149s	user 0.098s	sys 0.049s Metrics: {"bytes_written":9189657,"cfile_init":1,"compiler_manager_pool.queue_time_us":726,"delete_count":0,"dirs.queue_time_us":123,"dirs.run_cpu_time_us":234,"dirs.run_wall_time_us":1062,"drs_written":1,"lbm_read_time_us":129,"lbm_reads_lt_1ms":4,"lbm_write_time_us":37074,"lbm_writes_lt_1ms":581,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"spinlock_wait_cycles":177536,"thread_start_us":154,"threads_started":1,"update_count":1120}
I20260812 06:17:11.522084 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling LogGCOp(b27206ab2c8841239d010ee8043ecd4b): free 8725963 bytes of WAL
I20260812 06:17:11.522559 30936 log_reader.cc:385] T b27206ab2c8841239d010ee8043ecd4b: removed 1 log segments from log reader
I20260812 06:17:11.522704 30936 log.cc:1079] T b27206ab2c8841239d010ee8043ecd4b P 011c9100bb6c4a7d9d12071452b77e5e: Deleting log segment in path: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430933609-30815-0/minicluster-data/ts-0-root/wals/b27206ab2c8841239d010ee8043ecd4b/wal-000000001 (ops 1-6)
I20260812 06:17:11.526376 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: LogGCOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.004s	user 0.003s	sys 0.001s Metrics: {}
I20260812 06:17:11.527016 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b): perf score=1.196750
I20260812 06:17:11.540249 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.013s	user 0.010s	sys 0.001s Metrics: {"bytes_written":3118055,"delete_count":0,"lbm_write_time_us":4689,"lbm_writes_lt_1ms":79,"reinsert_count":0,"update_count":380}
I20260812 06:17:11.540784 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling UndoDeltaBlockGCOp(b27206ab2c8841239d010ee8043ecd4b): 12308959 bytes on disk
I20260812 06:17:11.541407 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: UndoDeltaBlockGCOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4}
I20260812 06:17:11.541900 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling MajorDeltaCompactionOp(b27206ab2c8841239d010ee8043ecd4b): perf score=1.000000
I20260812 06:17:11.671510 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: MajorDeltaCompactionOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.129s	user 0.087s	sys 0.036s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16528875,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1147,"lbm_read_time_us":8358,"lbm_reads_lt_1ms":360,"lbm_write_time_us":22242,"lbm_writes_lt_1ms":343,"mutex_wait_us":183,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":9344,"thread_start_us":361,"threads_started":5,"update_count":1500}
I20260812 06:17:11.672192 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b): perf score=10.126437
I20260812 06:17:11.724956 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.053s	user 0.033s	sys 0.003s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":16732,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:11.725607 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b): perf score=2.188937
I20260812 06:17:11.740269 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.014s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5256,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:11.741097 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling MajorDeltaCompactionOp(b27206ab2c8841239d010ee8043ecd4b): perf score=1.000000
I20260812 06:17:11.893221 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: MajorDeltaCompactionOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.152s	user 0.132s	sys 0.019s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631314,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":394,"lbm_read_time_us":10522,"lbm_reads_lt_1ms":472,"lbm_write_time_us":30442,"lbm_writes_lt_1ms":443,"mutex_wait_us":68,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":25216,"update_count":2000}
I20260812 06:17:11.893849 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b): perf score=10.126437
I20260812 06:17:11.947559 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.054s	user 0.021s	sys 0.031s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20071,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:11.948158 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b): perf score=2.188937
I20260812 06:17:11.959800 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4302,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:11.960553 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling MajorDeltaCompactionOp(b27206ab2c8841239d010ee8043ecd4b): perf score=1.000000
I20260812 06:17:12.118782 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: MajorDeltaCompactionOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.158s	user 0.122s	sys 0.035s 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":310,"lbm_read_time_us":11504,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25782,"lbm_writes_lt_1ms":443,"mutex_wait_us":25,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:17:12.119735 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b): perf score=10.126437
I20260812 06:17:12.167598 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.047s	user 0.025s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20224,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:12.168193 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b): perf score=2.188937
I20260812 06:17:12.182194 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.014s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4764,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:12.182790 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling MajorDeltaCompactionOp(b27206ab2c8841239d010ee8043ecd4b): perf score=1.000000
I20260812 06:17:12.311161 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: MajorDeltaCompactionOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.128s	user 0.108s	sys 0.020s 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":163,"lbm_read_time_us":8810,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25736,"lbm_writes_lt_1ms":443,"mutex_wait_us":40,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":25856,"update_count":2000}
I20260812 06:17:12.311862 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b): perf score=10.126437
I20260812 06:17:12.353138 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.041s	user 0.027s	sys 0.011s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17375,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:12.353873 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b): perf score=2.188937
I20260812 06:17:12.369125 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5187,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:12.369683 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling MajorDeltaCompactionOp(b27206ab2c8841239d010ee8043ecd4b): perf score=1.000000
I20260812 06:17:12.511513 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: MajorDeltaCompactionOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.142s	user 0.116s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":859,"lbm_read_time_us":9657,"lbm_reads_lt_1ms":464,"lbm_write_time_us":29018,"lbm_writes_lt_1ms":443,"mutex_wait_us":43,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14592,"update_count":2000}
I20260812 06:17:12.512698 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b): perf score=10.126437
I20260812 06:17:12.554685 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.042s	user 0.026s	sys 0.011s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16770,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:12.555202 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b): perf score=2.188937
I20260812 06:17:12.566537 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.011s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4258,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:12.567344 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling MajorDeltaCompactionOp(b27206ab2c8841239d010ee8043ecd4b): perf score=1.000000
I20260812 06:17:12.701656 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: MajorDeltaCompactionOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.134s	user 0.100s	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":235,"lbm_read_time_us":8779,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24853,"lbm_writes_lt_1ms":443,"mutex_wait_us":2,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:17:12.702450 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b): perf score=10.126437
I20260812 06:17:12.750753 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.048s	user 0.026s	sys 0.021s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16771,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:12.751410 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b): perf score=2.188937
I20260812 06:17:12.762792 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.011s	user 0.004s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4214,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:12.763324 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling MajorDeltaCompactionOp(b27206ab2c8841239d010ee8043ecd4b): perf score=1.000000
I20260812 06:17:12.911056 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: MajorDeltaCompactionOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.148s	user 0.095s	sys 0.052s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":347,"lbm_read_time_us":12365,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24133,"lbm_writes_lt_1ms":443,"mutex_wait_us":97,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8832,"update_count":2000}
I20260812 06:17:12.911816 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b): perf score=10.126437
I20260812 06:17:12.964061 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.052s	user 0.027s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18212,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:12.964682 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b): perf score=2.188937
I20260812 06:17:12.978368 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.013s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4719,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:12.978888 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling FlushMRSOp(b27206ab2c8841239d010ee8043ecd4b): perf score=1.000000
I20260812 06:17:13.008070 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: FlushMRSOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.029s	user 0.026s	sys 0.001s Metrics: {"bytes_written":1275444,"cfile_init":1,"dirs.queue_time_us":70,"dirs.run_cpu_time_us":274,"dirs.run_wall_time_us":1474,"drs_written":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2040,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:13.009075 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling LogGCOp(b27206ab2c8841239d010ee8043ecd4b): free 136728218 bytes of WAL
I20260812 06:17:13.009410 30936 log_reader.cc:385] T b27206ab2c8841239d010ee8043ecd4b: removed 13 log segments from log reader
I20260812 06:17:13.009474 30936 log.cc:1079] T b27206ab2c8841239d010ee8043ecd4b P 011c9100bb6c4a7d9d12071452b77e5e: Deleting log segment in path: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430933609-30815-0/minicluster-data/ts-0-root/wals/b27206ab2c8841239d010ee8043ecd4b/wal-000000002 (ops 7-11)
I20260812 06:17:13.009516 30936 log.cc:1079] T b27206ab2c8841239d010ee8043ecd4b P 011c9100bb6c4a7d9d12071452b77e5e: Deleting log segment in path: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430933609-30815-0/minicluster-data/ts-0-root/wals/b27206ab2c8841239d010ee8043ecd4b/wal-000000003 (ops 12-16)
I20260812 06:17:13.009539 30936 log.cc:1079] T b27206ab2c8841239d010ee8043ecd4b P 011c9100bb6c4a7d9d12071452b77e5e: Deleting log segment in path: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430933609-30815-0/minicluster-data/ts-0-root/wals/b27206ab2c8841239d010ee8043ecd4b/wal-000000004 (ops 17-21)
I20260812 06:17:13.009569 30936 log.cc:1079] T b27206ab2c8841239d010ee8043ecd4b P 011c9100bb6c4a7d9d12071452b77e5e: Deleting log segment in path: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430933609-30815-0/minicluster-data/ts-0-root/wals/b27206ab2c8841239d010ee8043ecd4b/wal-000000005 (ops 22-26)
I20260812 06:17:13.009596 30936 log.cc:1079] T b27206ab2c8841239d010ee8043ecd4b P 011c9100bb6c4a7d9d12071452b77e5e: Deleting log segment in path: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430933609-30815-0/minicluster-data/ts-0-root/wals/b27206ab2c8841239d010ee8043ecd4b/wal-000000006 (ops 27-31)
I20260812 06:17:13.009629 30936 log.cc:1079] T b27206ab2c8841239d010ee8043ecd4b P 011c9100bb6c4a7d9d12071452b77e5e: Deleting log segment in path: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430933609-30815-0/minicluster-data/ts-0-root/wals/b27206ab2c8841239d010ee8043ecd4b/wal-000000007 (ops 32-36)
I20260812 06:17:13.009657 30936 log.cc:1079] T b27206ab2c8841239d010ee8043ecd4b P 011c9100bb6c4a7d9d12071452b77e5e: Deleting log segment in path: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430933609-30815-0/minicluster-data/ts-0-root/wals/b27206ab2c8841239d010ee8043ecd4b/wal-000000008 (ops 37-41)
I20260812 06:17:13.009687 30936 log.cc:1079] T b27206ab2c8841239d010ee8043ecd4b P 011c9100bb6c4a7d9d12071452b77e5e: Deleting log segment in path: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430933609-30815-0/minicluster-data/ts-0-root/wals/b27206ab2c8841239d010ee8043ecd4b/wal-000000009 (ops 42-46)
I20260812 06:17:13.009714 30936 log.cc:1079] T b27206ab2c8841239d010ee8043ecd4b P 011c9100bb6c4a7d9d12071452b77e5e: Deleting log segment in path: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430933609-30815-0/minicluster-data/ts-0-root/wals/b27206ab2c8841239d010ee8043ecd4b/wal-000000010 (ops 47-51)
I20260812 06:17:13.009743 30936 log.cc:1079] T b27206ab2c8841239d010ee8043ecd4b P 011c9100bb6c4a7d9d12071452b77e5e: Deleting log segment in path: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430933609-30815-0/minicluster-data/ts-0-root/wals/b27206ab2c8841239d010ee8043ecd4b/wal-000000011 (ops 52-56)
I20260812 06:17:13.009771 30936 log.cc:1079] T b27206ab2c8841239d010ee8043ecd4b P 011c9100bb6c4a7d9d12071452b77e5e: Deleting log segment in path: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430933609-30815-0/minicluster-data/ts-0-root/wals/b27206ab2c8841239d010ee8043ecd4b/wal-000000012 (ops 57-61)
I20260812 06:17:13.009801 30936 log.cc:1079] T b27206ab2c8841239d010ee8043ecd4b P 011c9100bb6c4a7d9d12071452b77e5e: Deleting log segment in path: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430933609-30815-0/minicluster-data/ts-0-root/wals/b27206ab2c8841239d010ee8043ecd4b/wal-000000013 (ops 62-66)
I20260812 06:17:13.009835 30936 log.cc:1079] T b27206ab2c8841239d010ee8043ecd4b P 011c9100bb6c4a7d9d12071452b77e5e: Deleting log segment in path: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430933609-30815-0/minicluster-data/ts-0-root/wals/b27206ab2c8841239d010ee8043ecd4b/wal-000000014 (ops 67-71)
I20260812 06:17:13.046468 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: LogGCOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.037s	user 0.000s	sys 0.037s Metrics: {}
I20260812 06:17:13.047026 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling UndoDeltaBlockGCOp(b27206ab2c8841239d010ee8043ecd4b): 483 bytes on disk
I20260812 06:17:13.047501 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: UndoDeltaBlockGCOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4}
I20260812 06:17:13.047959 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b): perf score=3.181125
I20260812 06:17:13.060194 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.012s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4553933,"delete_count":0,"lbm_write_time_us":4608,"lbm_writes_lt_1ms":114,"reinsert_count":0,"update_count":555}
I20260812 06:17:13.060854 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b): perf score=2.188937
I20260812 06:17:13.080173 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.019s	user 0.000s	sys 0.017s Metrics: {"bytes_written":3651380,"delete_count":0,"lbm_write_time_us":3687,"lbm_writes_lt_1ms":92,"reinsert_count":0,"update_count":445}
I20260812 06:17:13.080708 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling MajorDeltaCompactionOp(b27206ab2c8841239d010ee8043ecd4b): perf score=1.000000
I20260812 06:17:13.302456 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: MajorDeltaCompactionOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.222s	user 0.151s	sys 0.061s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836369,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":2373,"lbm_read_time_us":14280,"lbm_reads_lt_1ms":674,"lbm_write_time_us":37233,"lbm_writes_lt_1ms":643,"mutex_wait_us":1365,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":13952,"thread_start_us":127,"threads_started":1,"update_count":3000}
I20260812 06:17:13.303174 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b): perf score=14.095187
I20260812 06:17:13.380107 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.077s	user 0.027s	sys 0.048s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":29812,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:17:13.380781 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b): perf score=2.188937
I20260812 06:17:13.393280 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.012s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4530,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:13.393955 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling MajorDeltaCompactionOp(b27206ab2c8841239d010ee8043ecd4b): perf score=1.000000
I20260812 06:17:13.607496 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: MajorDeltaCompactionOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.213s	user 0.118s	sys 0.089s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":254,"lbm_read_time_us":15360,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33246,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":22144,"update_count":2500}
I20260812 06:17:13.608054 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b): perf score=14.095187
I20260812 06:17:13.677615 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.069s	user 0.045s	sys 0.020s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":31156,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:17:13.678371 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b): perf score=2.188937
I20260812 06:17:13.690011 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4028,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:13.690613 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling MajorDeltaCompactionOp(b27206ab2c8841239d010ee8043ecd4b): perf score=1.000000
I20260812 06:17:13.891598 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: MajorDeltaCompactionOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.201s	user 0.128s	sys 0.065s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":221,"lbm_read_time_us":10891,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34212,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":542,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":25728,"update_count":2500}
I20260812 06:17:13.892259 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b): perf score=14.095187
I20260812 06:17:13.956655 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.064s	user 0.034s	sys 0.028s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":28477,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:13.957362 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b): perf score=2.188937
I20260812 06:17:13.969811 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4303,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:13.970451 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling MajorDeltaCompactionOp(b27206ab2c8841239d010ee8043ecd4b): perf score=1.000000
I20260812 06:17:14.129814 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: MajorDeltaCompactionOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.159s	user 0.121s	sys 0.032s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":750,"lbm_read_time_us":12787,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28605,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2500}
I20260812 06:17:14.130829 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b): perf score=11.118625
I20260812 06:17:14.172261 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.041s	user 0.027s	sys 0.012s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":17807,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:14.173095 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b): perf score=2.188937
I20260812 06:17:14.187681 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.014s	user 0.004s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4862,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:14.188885 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling MajorDeltaCompactionOp(b27206ab2c8841239d010ee8043ecd4b): perf score=1.000000
I20260812 06:17:14.325238 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: MajorDeltaCompactionOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.136s	user 0.114s	sys 0.019s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631303,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1080,"lbm_read_time_us":9351,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24666,"lbm_writes_lt_1ms":443,"mutex_wait_us":2,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2944,"update_count":2000}
I20260812 06:17:14.326190 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b): perf score=10.126437
I20260812 06:17:14.367750 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.041s	user 0.018s	sys 0.012s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":14103,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:14.368427 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling MajorDeltaCompactionOp(b27206ab2c8841239d010ee8043ecd4b): perf score=1.000000
I20260812 06:17:14.479628 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: MajorDeltaCompactionOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.111s	user 0.102s	sys 0.008s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16528780,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1246,"lbm_read_time_us":7844,"lbm_reads_lt_1ms":363,"lbm_write_time_us":19510,"lbm_writes_lt_1ms":343,"mutex_wait_us":374,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":1500}
I20260812 06:17:14.480239 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b): perf score=10.126437
I20260812 06:17:14.528164 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.048s	user 0.026s	sys 0.009s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15827,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:14.528687 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b): perf score=2.188937
I20260812 06:17:14.540653 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.012s	user 0.000s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4347,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:14.541314 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling FlushMRSOp(b27206ab2c8841239d010ee8043ecd4b): perf score=1.000000
I20260812 06:17:14.571230 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: FlushMRSOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.030s	user 0.021s	sys 0.008s Metrics: {"bytes_written":1152514,"cfile_init":1,"dirs.queue_time_us":48,"dirs.run_cpu_time_us":242,"dirs.run_wall_time_us":1711,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1599,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:14.572083 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling LogGCOp(b27206ab2c8841239d010ee8043ecd4b): free 115943184 bytes of WAL
I20260812 06:17:14.572348 30936 log_reader.cc:385] T b27206ab2c8841239d010ee8043ecd4b: removed 11 log segments from log reader
I20260812 06:17:14.572392 30936 log.cc:1079] T b27206ab2c8841239d010ee8043ecd4b P 011c9100bb6c4a7d9d12071452b77e5e: Deleting log segment in path: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430933609-30815-0/minicluster-data/ts-0-root/wals/b27206ab2c8841239d010ee8043ecd4b/wal-000000015 (ops 72-76)
I20260812 06:17:14.572424 30936 log.cc:1079] T b27206ab2c8841239d010ee8043ecd4b P 011c9100bb6c4a7d9d12071452b77e5e: Deleting log segment in path: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430933609-30815-0/minicluster-data/ts-0-root/wals/b27206ab2c8841239d010ee8043ecd4b/wal-000000016 (ops 77-81)
I20260812 06:17:14.572492 30936 log.cc:1079] T b27206ab2c8841239d010ee8043ecd4b P 011c9100bb6c4a7d9d12071452b77e5e: Deleting log segment in path: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430933609-30815-0/minicluster-data/ts-0-root/wals/b27206ab2c8841239d010ee8043ecd4b/wal-000000017 (ops 82-86)
I20260812 06:17:14.572535 30936 log.cc:1079] T b27206ab2c8841239d010ee8043ecd4b P 011c9100bb6c4a7d9d12071452b77e5e: Deleting log segment in path: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430933609-30815-0/minicluster-data/ts-0-root/wals/b27206ab2c8841239d010ee8043ecd4b/wal-000000018 (ops 87-91)
I20260812 06:17:14.572578 30936 log.cc:1079] T b27206ab2c8841239d010ee8043ecd4b P 011c9100bb6c4a7d9d12071452b77e5e: Deleting log segment in path: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430933609-30815-0/minicluster-data/ts-0-root/wals/b27206ab2c8841239d010ee8043ecd4b/wal-000000019 (ops 92-96)
I20260812 06:17:14.572625 30936 log.cc:1079] T b27206ab2c8841239d010ee8043ecd4b P 011c9100bb6c4a7d9d12071452b77e5e: Deleting log segment in path: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430933609-30815-0/minicluster-data/ts-0-root/wals/b27206ab2c8841239d010ee8043ecd4b/wal-000000020 (ops 97-101)
I20260812 06:17:14.572666 30936 log.cc:1079] T b27206ab2c8841239d010ee8043ecd4b P 011c9100bb6c4a7d9d12071452b77e5e: Deleting log segment in path: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430933609-30815-0/minicluster-data/ts-0-root/wals/b27206ab2c8841239d010ee8043ecd4b/wal-000000021 (ops 102-106)
I20260812 06:17:14.572710 30936 log.cc:1079] T b27206ab2c8841239d010ee8043ecd4b P 011c9100bb6c4a7d9d12071452b77e5e: Deleting log segment in path: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430933609-30815-0/minicluster-data/ts-0-root/wals/b27206ab2c8841239d010ee8043ecd4b/wal-000000022 (ops 107-111)
I20260812 06:17:14.572749 30936 log.cc:1079] T b27206ab2c8841239d010ee8043ecd4b P 011c9100bb6c4a7d9d12071452b77e5e: Deleting log segment in path: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430933609-30815-0/minicluster-data/ts-0-root/wals/b27206ab2c8841239d010ee8043ecd4b/wal-000000023 (ops 112-116)
I20260812 06:17:14.572789 30936 log.cc:1079] T b27206ab2c8841239d010ee8043ecd4b P 011c9100bb6c4a7d9d12071452b77e5e: Deleting log segment in path: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430933609-30815-0/minicluster-data/ts-0-root/wals/b27206ab2c8841239d010ee8043ecd4b/wal-000000024 (ops 117-121)
I20260812 06:17:14.572829 30936 log.cc:1079] T b27206ab2c8841239d010ee8043ecd4b P 011c9100bb6c4a7d9d12071452b77e5e: Deleting log segment in path: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430933609-30815-0/minicluster-data/ts-0-root/wals/b27206ab2c8841239d010ee8043ecd4b/wal-000000025 (ops 122-126)
I20260812 06:17:14.600574 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: LogGCOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.028s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:17:14.601125 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b): perf score=3.181125
I20260812 06:17:14.620031 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.019s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":4720,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:14.620591 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling UndoDeltaBlockGCOp(b27206ab2c8841239d010ee8043ecd4b): 446 bytes on disk
I20260812 06:17:14.621130 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: UndoDeltaBlockGCOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":88,"lbm_reads_lt_1ms":4}
I20260812 06:17:14.621860 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b): perf score=2.188937
I20260812 06:17:14.632800 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4261,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:14.633374 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling MajorDeltaCompactionOp(b27206ab2c8841239d010ee8043ecd4b): perf score=1.000000
I20260812 06:17:14.854650 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: MajorDeltaCompactionOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.221s	user 0.165s	sys 0.055s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836363,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":463,"lbm_read_time_us":15617,"lbm_reads_lt_1ms":674,"lbm_write_time_us":41703,"lbm_writes_lt_1ms":643,"mutex_wait_us":18,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":17024,"thread_start_us":84,"threads_started":1,"update_count":3000}
I20260812 06:17:14.855405 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b): perf score=14.095187
I20260812 06:17:14.931888 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.076s	user 0.029s	sys 0.033s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":24935,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:14.932578 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b): perf score=2.188937
I20260812 06:17:14.945731 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5129,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:14.946386 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling MajorDeltaCompactionOp(b27206ab2c8841239d010ee8043ecd4b): perf score=1.000000
I20260812 06:17:15.132371 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: MajorDeltaCompactionOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.186s	user 0.120s	sys 0.065s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":963,"lbm_read_time_us":14392,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33322,"lbm_writes_lt_1ms":543,"mutex_wait_us":29,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":22656,"update_count":2500}
I20260812 06:17:15.133046 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b): perf score=10.126437
I20260812 06:17:15.172883 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.040s	user 0.025s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17162,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:15.173870 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b): perf score=2.188937
I20260812 06:17:15.192965 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.019s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5456,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:15.193585 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling MajorDeltaCompactionOp(b27206ab2c8841239d010ee8043ecd4b): perf score=1.000000
I20260812 06:17:15.348764 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: MajorDeltaCompactionOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.155s	user 0.112s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1177,"lbm_read_time_us":8429,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24706,"lbm_writes_lt_1ms":443,"mutex_wait_us":94,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:15.349422 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b): perf score=11.118625
I20260812 06:17:15.384282 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.035s	user 0.025s	sys 0.007s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14764,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:15.385120 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b): perf score=2.188937
I20260812 06:17:15.405174 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.020s	user 0.003s	sys 0.012s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6223,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:15.405829 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling MajorDeltaCompactionOp(b27206ab2c8841239d010ee8043ecd4b): perf score=1.000000
I20260812 06:17:15.534192 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: MajorDeltaCompactionOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.128s	user 0.109s	sys 0.019s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631303,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":339,"lbm_read_time_us":7819,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25214,"lbm_writes_lt_1ms":443,"mutex_wait_us":30,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11648,"update_count":2000}
I20260812 06:17:15.534917 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b): perf score=11.118625
I20260812 06:17:15.581009 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.046s	user 0.023s	sys 0.020s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":20235,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":311,"reinsert_count":0,"update_count":1550}
I20260812 06:17:15.581599 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b): perf score=2.188937
I20260812 06:17:15.608363 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.026s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4610,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:15.608920 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b): perf score=2.188937
I20260812 06:17:15.619935 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4024,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:15.620487 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling MajorDeltaCompactionOp(b27206ab2c8841239d010ee8043ecd4b): perf score=1.000000
I20260812 06:17:15.776443 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: MajorDeltaCompactionOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.156s	user 0.112s	sys 0.044s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733834,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":231,"lbm_read_time_us":11071,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29981,"lbm_writes_lt_1ms":543,"mutex_wait_us":68,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11136,"update_count":2500}
I20260812 06:17:15.780833 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b): perf score=10.126437
I20260812 06:17:15.816233 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.035s	user 0.025s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15474,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:15.817004 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b): perf score=2.188937
I20260812 06:17:15.832988 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.016s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5458,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:15.833647 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling MajorDeltaCompactionOp(b27206ab2c8841239d010ee8043ecd4b): perf score=1.000000
I20260812 06:17:15.988215 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: MajorDeltaCompactionOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.154s	user 0.102s	sys 0.052s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":699,"lbm_read_time_us":9569,"lbm_reads_lt_1ms":468,"lbm_write_time_us":26430,"lbm_writes_lt_1ms":443,"mutex_wait_us":58,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:17:15.989048 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b): perf score=11.118625
I20260812 06:17:16.029917 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.041s	user 0.030s	sys 0.007s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":17939,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:16.030941 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b): perf score=2.188937
I20260812 06:17:16.048455 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.017s	user 0.005s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5841,"lbm_writes_lt_1ms":93,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":450}
I20260812 06:17:16.049000 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling FlushMRSOp(b27206ab2c8841239d010ee8043ecd4b): perf score=1.000000
I20260812 06:17:16.087822 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: FlushMRSOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.039s	user 0.037s	sys 0.000s Metrics: {"bytes_written":1193505,"cfile_init":1,"dirs.queue_time_us":99,"dirs.run_cpu_time_us":367,"dirs.run_wall_time_us":1637,"drs_written":1,"lbm_read_time_us":42,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1599,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:16.088625 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling LogGCOp(b27206ab2c8841239d010ee8043ecd4b): free 108535622 bytes of WAL
I20260812 06:17:16.088884 30936 log_reader.cc:385] T b27206ab2c8841239d010ee8043ecd4b: removed 11 log segments from log reader
I20260812 06:17:16.088953 30936 log.cc:1079] T b27206ab2c8841239d010ee8043ecd4b P 011c9100bb6c4a7d9d12071452b77e5e: Deleting log segment in path: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430933609-30815-0/minicluster-data/ts-0-root/wals/b27206ab2c8841239d010ee8043ecd4b/wal-000000026 (ops 127-131)
I20260812 06:17:16.089008 30936 log.cc:1079] T b27206ab2c8841239d010ee8043ecd4b P 011c9100bb6c4a7d9d12071452b77e5e: Deleting log segment in path: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430933609-30815-0/minicluster-data/ts-0-root/wals/b27206ab2c8841239d010ee8043ecd4b/wal-000000027 (ops 132-136)
I20260812 06:17:16.089077 30936 log.cc:1079] T b27206ab2c8841239d010ee8043ecd4b P 011c9100bb6c4a7d9d12071452b77e5e: Deleting log segment in path: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430933609-30815-0/minicluster-data/ts-0-root/wals/b27206ab2c8841239d010ee8043ecd4b/wal-000000028 (ops 137-140)
I20260812 06:17:16.089128 30936 log.cc:1079] T b27206ab2c8841239d010ee8043ecd4b P 011c9100bb6c4a7d9d12071452b77e5e: Deleting log segment in path: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430933609-30815-0/minicluster-data/ts-0-root/wals/b27206ab2c8841239d010ee8043ecd4b/wal-000000029 (ops 141-145)
I20260812 06:17:16.089164 30936 log.cc:1079] T b27206ab2c8841239d010ee8043ecd4b P 011c9100bb6c4a7d9d12071452b77e5e: Deleting log segment in path: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430933609-30815-0/minicluster-data/ts-0-root/wals/b27206ab2c8841239d010ee8043ecd4b/wal-000000030 (ops 146-150)
I20260812 06:17:16.089202 30936 log.cc:1079] T b27206ab2c8841239d010ee8043ecd4b P 011c9100bb6c4a7d9d12071452b77e5e: Deleting log segment in path: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430933609-30815-0/minicluster-data/ts-0-root/wals/b27206ab2c8841239d010ee8043ecd4b/wal-000000031 (ops 151-155)
I20260812 06:17:16.089239 30936 log.cc:1079] T b27206ab2c8841239d010ee8043ecd4b P 011c9100bb6c4a7d9d12071452b77e5e: Deleting log segment in path: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430933609-30815-0/minicluster-data/ts-0-root/wals/b27206ab2c8841239d010ee8043ecd4b/wal-000000032 (ops 156-160)
I20260812 06:17:16.089273 30936 log.cc:1079] T b27206ab2c8841239d010ee8043ecd4b P 011c9100bb6c4a7d9d12071452b77e5e: Deleting log segment in path: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430933609-30815-0/minicluster-data/ts-0-root/wals/b27206ab2c8841239d010ee8043ecd4b/wal-000000033 (ops 161-165)
I20260812 06:17:16.089310 30936 log.cc:1079] T b27206ab2c8841239d010ee8043ecd4b P 011c9100bb6c4a7d9d12071452b77e5e: Deleting log segment in path: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430933609-30815-0/minicluster-data/ts-0-root/wals/b27206ab2c8841239d010ee8043ecd4b/wal-000000034 (ops 166-170)
I20260812 06:17:16.089345 30936 log.cc:1079] T b27206ab2c8841239d010ee8043ecd4b P 011c9100bb6c4a7d9d12071452b77e5e: Deleting log segment in path: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430933609-30815-0/minicluster-data/ts-0-root/wals/b27206ab2c8841239d010ee8043ecd4b/wal-000000035 (ops 171-174)
I20260812 06:17:16.089381 30936 log.cc:1079] T b27206ab2c8841239d010ee8043ecd4b P 011c9100bb6c4a7d9d12071452b77e5e: Deleting log segment in path: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430933609-30815-0/minicluster-data/ts-0-root/wals/b27206ab2c8841239d010ee8043ecd4b/wal-000000036 (ops 175-179)
I20260812 06:17:16.115432 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: LogGCOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.027s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:17:16.115904 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling UndoDeltaBlockGCOp(b27206ab2c8841239d010ee8043ecd4b): 463 bytes on disk
I20260812 06:17:16.116379 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: UndoDeltaBlockGCOp(b27206ab2c8841239d010ee8043ecd4b) 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:17:16.117019 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b): perf score=3.181125
I20260812 06:17:16.130280 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.013s	user 0.009s	sys 0.003s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4735,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:16.130779 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling LogGCOp(b27206ab2c8841239d010ee8043ecd4b): free 8767197 bytes of WAL
I20260812 06:17:16.131003 30936 log_reader.cc:385] T b27206ab2c8841239d010ee8043ecd4b: removed 1 log segments from log reader
I20260812 06:17:16.131048 30936 log.cc:1079] T b27206ab2c8841239d010ee8043ecd4b P 011c9100bb6c4a7d9d12071452b77e5e: Deleting log segment in path: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430933609-30815-0/minicluster-data/ts-0-root/wals/b27206ab2c8841239d010ee8043ecd4b/wal-000000037 (ops 180-184)
I20260812 06:17:16.132861 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: LogGCOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:17:16.133236 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b): perf score=2.188937
I20260812 06:17:16.143621 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3812,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:16.144398 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling MajorDeltaCompactionOp(b27206ab2c8841239d010ee8043ecd4b): perf score=1.000000
I20260812 06:17:16.343523 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: MajorDeltaCompactionOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.199s	user 0.136s	sys 0.060s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836355,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":758,"lbm_read_time_us":12585,"lbm_reads_lt_1ms":674,"lbm_write_time_us":34961,"lbm_writes_lt_1ms":643,"mutex_wait_us":108,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":96,"threads_started":1,"update_count":3000}
I20260812 06:17:16.344220 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b): perf score=14.095187
I20260812 06:17:16.403795 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.059s	user 0.040s	sys 0.012s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":22600,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:16.404369 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b): perf score=2.188937
I20260812 06:17:16.415629 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4288,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:16.416229 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling MajorDeltaCompactionOp(b27206ab2c8841239d010ee8043ecd4b): perf score=1.000000
I20260812 06:17:16.566098 30815 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.324s	user 1.908s	sys 0.174s
I20260812 06:17:16.598085 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: MajorDeltaCompactionOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.182s	user 0.120s	sys 0.059s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733722,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"lbm_read_time_us":13067,"lbm_reads_lt_1ms":568,"lbm_write_time_us":31382,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":31488,"update_count":2500}
I20260812 06:17:16.598701 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b): perf score=10.126437
I20260812 06:17:16.623697 30815 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.057s	user 0.000s	sys 0.003s
I20260812 06:17:16.624444 30815 tablet_server.cc:179] TabletServer@127.30.23.193:0 shutting down...
I20260812 06:17:16.629148 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: FlushDeltaMemStoresOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.030s	user 0.018s	sys 0.009s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":12770,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:16.629871 31006 maintenance_manager.cc:419] P 011c9100bb6c4a7d9d12071452b77e5e: Scheduling MajorDeltaCompactionOp(b27206ab2c8841239d010ee8043ecd4b): perf score=1.000000
I20260812 06:17:16.733055 30936 maintenance_manager.cc:643] P 011c9100bb6c4a7d9d12071452b77e5e: MajorDeltaCompactionOp(b27206ab2c8841239d010ee8043ecd4b) complete. Timing: real 0.103s	user 0.075s	sys 0.028s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16528782,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":426,"lbm_read_time_us":6364,"lbm_reads_lt_1ms":367,"lbm_write_time_us":17763,"lbm_writes_lt_1ms":343,"mutex_wait_us":26,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":9984,"update_count":1500}
I20260812 06:17:16.733826 30815 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:16.734354 30815 tablet_replica.cc:333] T b27206ab2c8841239d010ee8043ecd4b P 011c9100bb6c4a7d9d12071452b77e5e: stopping tablet replica
I20260812 06:17:16.734608 30815 raft_consensus.cc:2243] T b27206ab2c8841239d010ee8043ecd4b P 011c9100bb6c4a7d9d12071452b77e5e [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:16.734882 30815 raft_consensus.cc:2272] T b27206ab2c8841239d010ee8043ecd4b P 011c9100bb6c4a7d9d12071452b77e5e [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:16.751658 30815 tablet_server.cc:196] TabletServer@127.30.23.193:0 shutdown complete.
I20260812 06:17:16.767817 30815 master.cc:562] Master@127.30.23.254:34873 shutting down...
I20260812 06:17:16.771806 30815 raft_consensus.cc:2243] T 00000000000000000000000000000000 P e3dfc4ad91b24ebdb68bb20bc800bd79 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:16.772012 30815 raft_consensus.cc:2272] T 00000000000000000000000000000000 P e3dfc4ad91b24ebdb68bb20bc800bd79 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:16.772065 30815 tablet_replica.cc:333] T 00000000000000000000000000000000 P e3dfc4ad91b24ebdb68bb20bc800bd79: stopping tablet replica
I20260812 06:17:16.784811 30815 master.cc:584] Master@127.30.23.254:34873 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5944 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:17:16.889636 30815 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.30.23.254:44135
I20260812 06:17:16.890010 30815 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:16.892572 31044 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:17:16.892640 31043 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:17:16.892630 31046 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:17:16.892628 30815 server_base.cc:1061] running on GCE node
I20260812 06:17:16.892998 30815 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:16.893041 30815 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:17:16.893057 30815 hybrid_clock.cc:648] HybridClock initialized: now 1786515436893057 us; error 0 us; skew 500 ppm
I20260812 06:17:16.894053 30815 webserver.cc:533] Webserver started at http://127.30.23.254:39637/ using document root <none> and password file <none>
I20260812 06:17:16.894342 30815 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:16.894398 30815 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:16.894456 30815 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:16.894878 30815 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430933609-30815-0/minicluster-data/master-0-root/instance:
uuid: "b19827918bbe494eb905bfc94f04a503"
format_stamp: "Formatted at 2026-08-12 06:17:16 on dist-test-slave-9jjr"
I20260812 06:17:16.896566 30815 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:17:16.897701 31052 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:17:16.897979 30815 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:17:16.898088 30815 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430933609-30815-0/minicluster-data/master-0-root
uuid: "b19827918bbe494eb905bfc94f04a503"
format_stamp: "Formatted at 2026-08-12 06:17:16 on dist-test-slave-9jjr"
I20260812 06:17:16.898288 30815 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430933609-30815-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430933609-30815-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430933609-30815-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:17:16.911546 30815 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:16.912045 30815 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:16.916787 30815 rpc_server.cc:307] RPC server started. Bound to: 127.30.23.254:44135
I20260812 06:17:16.922477 31111 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:17:16.932520 31109 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.30.23.254:44135 every 8 connection(s)
I20260812 06:17:16.932852 31111 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P b19827918bbe494eb905bfc94f04a503: Bootstrap starting.
I20260812 06:17:16.933799 31111 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P b19827918bbe494eb905bfc94f04a503: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:16.935315 31111 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P b19827918bbe494eb905bfc94f04a503: No bootstrap required, opened a new log
I20260812 06:17:16.935823 31111 raft_consensus.cc:359] T 00000000000000000000000000000000 P b19827918bbe494eb905bfc94f04a503 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b19827918bbe494eb905bfc94f04a503" member_type: VOTER }
I20260812 06:17:16.935954 31111 raft_consensus.cc:385] T 00000000000000000000000000000000 P b19827918bbe494eb905bfc94f04a503 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:16.936003 31111 raft_consensus.cc:740] T 00000000000000000000000000000000 P b19827918bbe494eb905bfc94f04a503 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: b19827918bbe494eb905bfc94f04a503, State: Initialized, Role: FOLLOWER
I20260812 06:17:16.936267 31111 consensus_queue.cc:260] T 00000000000000000000000000000000 P b19827918bbe494eb905bfc94f04a503 [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: "b19827918bbe494eb905bfc94f04a503" member_type: VOTER }
I20260812 06:17:16.936417 31111 raft_consensus.cc:399] T 00000000000000000000000000000000 P b19827918bbe494eb905bfc94f04a503 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:16.936472 31111 raft_consensus.cc:493] T 00000000000000000000000000000000 P b19827918bbe494eb905bfc94f04a503 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:16.936535 31111 raft_consensus.cc:3060] T 00000000000000000000000000000000 P b19827918bbe494eb905bfc94f04a503 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:16.937402 31111 raft_consensus.cc:515] T 00000000000000000000000000000000 P b19827918bbe494eb905bfc94f04a503 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b19827918bbe494eb905bfc94f04a503" member_type: VOTER }
I20260812 06:17:16.937583 31111 leader_election.cc:304] T 00000000000000000000000000000000 P b19827918bbe494eb905bfc94f04a503 [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: b19827918bbe494eb905bfc94f04a503; no voters: 
I20260812 06:17:16.937845 31111 leader_election.cc:290] T 00000000000000000000000000000000 P b19827918bbe494eb905bfc94f04a503 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:16.937995 31114 raft_consensus.cc:2804] T 00000000000000000000000000000000 P b19827918bbe494eb905bfc94f04a503 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:16.938297 31114 raft_consensus.cc:697] T 00000000000000000000000000000000 P b19827918bbe494eb905bfc94f04a503 [term 1 LEADER]: Becoming Leader. State: Replica: b19827918bbe494eb905bfc94f04a503, State: Running, Role: LEADER
I20260812 06:17:16.938455 31114 consensus_queue.cc:237] T 00000000000000000000000000000000 P b19827918bbe494eb905bfc94f04a503 [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: "b19827918bbe494eb905bfc94f04a503" member_type: VOTER }
I20260812 06:17:16.938515 31111 sys_catalog.cc:565] T 00000000000000000000000000000000 P b19827918bbe494eb905bfc94f04a503 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:16.938956 31117 sys_catalog.cc:455] T 00000000000000000000000000000000 P b19827918bbe494eb905bfc94f04a503 [sys.catalog]: SysCatalogTable state changed. Reason: New leader b19827918bbe494eb905bfc94f04a503. Latest consensus state: current_term: 1 leader_uuid: "b19827918bbe494eb905bfc94f04a503" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b19827918bbe494eb905bfc94f04a503" member_type: VOTER } }
I20260812 06:17:16.938938 31116 sys_catalog.cc:455] T 00000000000000000000000000000000 P b19827918bbe494eb905bfc94f04a503 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "b19827918bbe494eb905bfc94f04a503" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b19827918bbe494eb905bfc94f04a503" member_type: VOTER } }
I20260812 06:17:16.939092 31117 sys_catalog.cc:458] T 00000000000000000000000000000000 P b19827918bbe494eb905bfc94f04a503 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:16.939149 31116 sys_catalog.cc:458] T 00000000000000000000000000000000 P b19827918bbe494eb905bfc94f04a503 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:16.939740 31121 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:16.940747 31121 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:16.940987 30815 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:16.942900 31121 catalog_manager.cc:1383] Generated new cluster ID: 57b7307971b94ed38f58d4d4e74a8d64
I20260812 06:17:16.942961 31121 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:16.958694 31121 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:16.959378 31121 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:16.977701 31121 catalog_manager.cc:6092] T 00000000000000000000000000000000 P b19827918bbe494eb905bfc94f04a503: Generated new TSK 0
I20260812 06:17:16.977980 31121 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:17.005885 30815 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:17.008582 31137 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:17:17.008767 30815 server_base.cc:1061] running on GCE node
W20260812 06:17:17.008584 31134 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:17:17.008657 31135 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:17:17.009215 30815 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:17.009264 30815 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:17:17.009281 30815 hybrid_clock.cc:648] HybridClock initialized: now 1786515437009281 us; error 0 us; skew 500 ppm
I20260812 06:17:17.010313 30815 webserver.cc:533] Webserver started at http://127.30.23.193:42917/ using document root <none> and password file <none>
I20260812 06:17:17.010480 30815 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:17.010526 30815 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:17.010623 30815 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:17.011013 30815 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430933609-30815-0/minicluster-data/ts-0-root/instance:
uuid: "5b5a41849bc24164810226c43c2ce076"
format_stamp: "Formatted at 2026-08-12 06:17:17 on dist-test-slave-9jjr"
I20260812 06:17:17.012763 30815 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:17:17.014087 31142 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:17:17.014982 30815 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.000s	sys 0.001s
I20260812 06:17:17.015074 30815 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430933609-30815-0/minicluster-data/ts-0-root
uuid: "5b5a41849bc24164810226c43c2ce076"
format_stamp: "Formatted at 2026-08-12 06:17:17 on dist-test-slave-9jjr"
I20260812 06:17:17.015262 30815 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430933609-30815-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430933609-30815-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430933609-30815-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:17:17.021929 30815 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:17.022508 30815 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:17.022873 30815 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:17.023483 30815 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:17.023521 30815 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:17.023555 30815 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:17.023617 30815 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:17.028362 30815 rpc_server.cc:307] RPC server started. Bound to: 127.30.23.193:36835
I20260812 06:17:17.029036 31213 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.30.23.193:36835 every 8 connection(s)
I20260812 06:17:17.039443 31214 heartbeater.cc:344] Connected to a master server at 127.30.23.254:44135
I20260812 06:17:17.039682 31214 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:17.040014 31214 heartbeater.cc:507] Master 127.30.23.254:44135 requested a full tablet report, sending...
I20260812 06:17:17.040979 31071 ts_manager.cc:194] Registered new tserver with Master: 5b5a41849bc24164810226c43c2ce076 (127.30.23.193:36835)
I20260812 06:17:17.041702 30815 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012523725s
I20260812 06:17:17.042009 31071 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:58660
I20260812 06:17:17.050971 31071 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:58668:
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:17:17.061542 31177 tablet_service.cc:1511] Processing CreateTablet for tablet ce680e7cac394f86b7d1fcb49836f3b1 (DEFAULT_TABLE table=heavy-update-compaction-test [id=02ba1b332c984a08b6376878611c6260]), partition=
I20260812 06:17:17.061898 31177 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet ce680e7cac394f86b7d1fcb49836f3b1. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:17.064210 31229 tablet_bootstrap.cc:492] T ce680e7cac394f86b7d1fcb49836f3b1 P 5b5a41849bc24164810226c43c2ce076: Bootstrap starting.
I20260812 06:17:17.065289 31229 tablet_bootstrap.cc:654] T ce680e7cac394f86b7d1fcb49836f3b1 P 5b5a41849bc24164810226c43c2ce076: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:17.066601 31229 tablet_bootstrap.cc:492] T ce680e7cac394f86b7d1fcb49836f3b1 P 5b5a41849bc24164810226c43c2ce076: No bootstrap required, opened a new log
I20260812 06:17:17.066705 31229 ts_tablet_manager.cc:1403] T ce680e7cac394f86b7d1fcb49836f3b1 P 5b5a41849bc24164810226c43c2ce076: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:17:17.067257 31229 raft_consensus.cc:359] T ce680e7cac394f86b7d1fcb49836f3b1 P 5b5a41849bc24164810226c43c2ce076 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5b5a41849bc24164810226c43c2ce076" member_type: VOTER last_known_addr { host: "127.30.23.193" port: 36835 } }
I20260812 06:17:17.067389 31229 raft_consensus.cc:385] T ce680e7cac394f86b7d1fcb49836f3b1 P 5b5a41849bc24164810226c43c2ce076 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:17.067414 31229 raft_consensus.cc:740] T ce680e7cac394f86b7d1fcb49836f3b1 P 5b5a41849bc24164810226c43c2ce076 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 5b5a41849bc24164810226c43c2ce076, State: Initialized, Role: FOLLOWER
I20260812 06:17:17.067603 31229 consensus_queue.cc:260] T ce680e7cac394f86b7d1fcb49836f3b1 P 5b5a41849bc24164810226c43c2ce076 [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: "5b5a41849bc24164810226c43c2ce076" member_type: VOTER last_known_addr { host: "127.30.23.193" port: 36835 } }
I20260812 06:17:17.067711 31229 raft_consensus.cc:399] T ce680e7cac394f86b7d1fcb49836f3b1 P 5b5a41849bc24164810226c43c2ce076 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:17.067754 31229 raft_consensus.cc:493] T ce680e7cac394f86b7d1fcb49836f3b1 P 5b5a41849bc24164810226c43c2ce076 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:17.067847 31229 raft_consensus.cc:3060] T ce680e7cac394f86b7d1fcb49836f3b1 P 5b5a41849bc24164810226c43c2ce076 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:17.068835 31229 raft_consensus.cc:515] T ce680e7cac394f86b7d1fcb49836f3b1 P 5b5a41849bc24164810226c43c2ce076 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5b5a41849bc24164810226c43c2ce076" member_type: VOTER last_known_addr { host: "127.30.23.193" port: 36835 } }
I20260812 06:17:17.068969 31229 leader_election.cc:304] T ce680e7cac394f86b7d1fcb49836f3b1 P 5b5a41849bc24164810226c43c2ce076 [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: 5b5a41849bc24164810226c43c2ce076; no voters: 
I20260812 06:17:17.069327 31229 leader_election.cc:290] T ce680e7cac394f86b7d1fcb49836f3b1 P 5b5a41849bc24164810226c43c2ce076 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:17.069496 31231 raft_consensus.cc:2804] T ce680e7cac394f86b7d1fcb49836f3b1 P 5b5a41849bc24164810226c43c2ce076 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:17.069744 31229 ts_tablet_manager.cc:1434] T ce680e7cac394f86b7d1fcb49836f3b1 P 5b5a41849bc24164810226c43c2ce076: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:17:17.069761 31231 raft_consensus.cc:697] T ce680e7cac394f86b7d1fcb49836f3b1 P 5b5a41849bc24164810226c43c2ce076 [term 1 LEADER]: Becoming Leader. State: Replica: 5b5a41849bc24164810226c43c2ce076, State: Running, Role: LEADER
I20260812 06:17:17.069800 31214 heartbeater.cc:499] Master 127.30.23.254:44135 was elected leader, sending a full tablet report...
I20260812 06:17:17.069998 31231 consensus_queue.cc:237] T ce680e7cac394f86b7d1fcb49836f3b1 P 5b5a41849bc24164810226c43c2ce076 [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: "5b5a41849bc24164810226c43c2ce076" member_type: VOTER last_known_addr { host: "127.30.23.193" port: 36835 } }
I20260812 06:17:17.071513 31071 catalog_manager.cc:5719] T ce680e7cac394f86b7d1fcb49836f3b1 P 5b5a41849bc24164810226c43c2ce076 reported cstate change: term changed from 0 to 1, leader changed from <none> to 5b5a41849bc24164810226c43c2ce076 (127.30.23.193). New cstate: current_term: 1 leader_uuid: "5b5a41849bc24164810226c43c2ce076" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5b5a41849bc24164810226c43c2ce076" member_type: VOTER last_known_addr { host: "127.30.23.193" port: 36835 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:17.133723 30815 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.054s	user 0.006s	sys 0.016s
I20260812 06:17:17.279913 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling FlushMRSOp(ce680e7cac394f86b7d1fcb49836f3b1): perf score=15.086190
I20260812 06:17:17.436447 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: FlushMRSOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.156s	user 0.106s	sys 0.043s Metrics: {"bytes_written":9435802,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":107,"dirs.run_cpu_time_us":198,"dirs.run_wall_time_us":1037,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":39457,"lbm_writes_lt_1ms":687,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"spinlock_wait_cycles":15104,"update_count":1150}
I20260812 06:17:17.437265 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling LogGCOp(ce680e7cac394f86b7d1fcb49836f3b1): free 20290830 bytes of WAL
I20260812 06:17:17.437552 31147 log_reader.cc:385] T ce680e7cac394f86b7d1fcb49836f3b1: removed 2 log segments from log reader
I20260812 06:17:17.437631 31147 log.cc:1079] T ce680e7cac394f86b7d1fcb49836f3b1 P 5b5a41849bc24164810226c43c2ce076: Deleting log segment in path: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430933609-30815-0/minicluster-data/ts-0-root/wals/ce680e7cac394f86b7d1fcb49836f3b1/wal-000000001 (ops 1-6)
I20260812 06:17:17.437690 31147 log.cc:1079] T ce680e7cac394f86b7d1fcb49836f3b1 P 5b5a41849bc24164810226c43c2ce076: Deleting log segment in path: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430933609-30815-0/minicluster-data/ts-0-root/wals/ce680e7cac394f86b7d1fcb49836f3b1/wal-000000002 (ops 7-10)
I20260812 06:17:17.443462 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: LogGCOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.006s	user 0.000s	sys 0.005s Metrics: {}
I20260812 06:17:17.443936 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1): perf score=1.196750
I20260812 06:17:17.455677 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.012s	user 0.004s	sys 0.006s Metrics: {"bytes_written":2871905,"delete_count":0,"lbm_write_time_us":3936,"lbm_writes_lt_1ms":73,"reinsert_count":0,"update_count":350}
I20260812 06:17:17.456346 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling UndoDeltaBlockGCOp(ce680e7cac394f86b7d1fcb49836f3b1): 16411377 bytes on disk
I20260812 06:17:17.456970 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: UndoDeltaBlockGCOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":87,"lbm_reads_lt_1ms":4}
I20260812 06:17:17.457445 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling MajorDeltaCompactionOp(ce680e7cac394f86b7d1fcb49836f3b1): perf score=1.000000
I20260812 06:17:17.574574 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: MajorDeltaCompactionOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.117s	user 0.082s	sys 0.035s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16528870,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":373,"lbm_read_time_us":9039,"lbm_reads_lt_1ms":364,"lbm_write_time_us":20910,"lbm_writes_lt_1ms":343,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":4608,"thread_start_us":351,"threads_started":5,"update_count":1500}
I20260812 06:17:17.575171 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1): perf score=10.126437
I20260812 06:17:17.623790 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.048s	user 0.024s	sys 0.017s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19085,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:17.624294 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1): perf score=2.188937
I20260812 06:17:17.647641 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.023s	user 0.007s	sys 0.015s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4515,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:17.648307 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling MajorDeltaCompactionOp(ce680e7cac394f86b7d1fcb49836f3b1): perf score=1.000000
I20260812 06:17:17.814522 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: MajorDeltaCompactionOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.166s	user 0.117s	sys 0.049s 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":1082,"lbm_read_time_us":13625,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27924,"lbm_writes_lt_1ms":443,"mutex_wait_us":373,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:17:17.815128 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1): perf score=11.118625
I20260812 06:17:17.864745 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.049s	user 0.021s	sys 0.026s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":22898,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:17:17.865293 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1): perf score=2.188937
I20260812 06:17:17.891364 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.026s	user 0.010s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5959,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:17.891883 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1): perf score=2.188937
I20260812 06:17:17.904066 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.012s	user 0.004s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4641,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:17.904862 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling MajorDeltaCompactionOp(ce680e7cac394f86b7d1fcb49836f3b1): perf score=1.000000
I20260812 06:17:18.067123 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: MajorDeltaCompactionOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.162s	user 0.124s	sys 0.032s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733834,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":509,"lbm_read_time_us":11970,"lbm_reads_lt_1ms":573,"lbm_write_time_us":31030,"lbm_writes_lt_1ms":543,"mutex_wait_us":26,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":19200,"update_count":2500}
I20260812 06:17:18.067991 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1): perf score=11.118625
I20260812 06:17:18.104619 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.036s	user 0.018s	sys 0.016s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":15217,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:18.105131 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1): perf score=2.188937
I20260812 06:17:18.118613 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4207,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:18.119446 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling MajorDeltaCompactionOp(ce680e7cac394f86b7d1fcb49836f3b1): perf score=1.000000
I20260812 06:17:18.246344 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: MajorDeltaCompactionOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.127s	user 0.096s	sys 0.031s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631305,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":145,"lbm_read_time_us":8332,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23862,"lbm_writes_lt_1ms":443,"mutex_wait_us":35,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:17:18.246990 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1): perf score=10.126437
I20260812 06:17:18.291389 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.044s	user 0.028s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18207,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:18.291970 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1): perf score=2.188937
I20260812 06:17:18.304131 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4301,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:18.304735 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling MajorDeltaCompactionOp(ce680e7cac394f86b7d1fcb49836f3b1): perf score=1.000000
I20260812 06:17:18.439883 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: MajorDeltaCompactionOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.135s	user 0.095s	sys 0.040s 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":573,"lbm_read_time_us":10148,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26460,"lbm_writes_lt_1ms":443,"mutex_wait_us":220,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9088,"update_count":2000}
I20260812 06:17:18.440482 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1): perf score=10.126437
I20260812 06:17:18.489593 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.049s	user 0.033s	sys 0.012s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16029,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:18.490402 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling MajorDeltaCompactionOp(ce680e7cac394f86b7d1fcb49836f3b1): perf score=1.000000
I20260812 06:17:18.624248 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: MajorDeltaCompactionOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.134s	user 0.108s	sys 0.025s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16528780,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":820,"lbm_read_time_us":9851,"lbm_reads_lt_1ms":363,"lbm_write_time_us":21745,"lbm_writes_lt_1ms":343,"mutex_wait_us":347,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":30592,"update_count":1500}
I20260812 06:17:18.624950 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1): perf score=10.126437
I20260812 06:17:18.677369 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.052s	user 0.031s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17641,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:18.677922 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1): perf score=2.188937
I20260812 06:17:18.689708 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4313,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:18.690413 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling FlushMRSOp(ce680e7cac394f86b7d1fcb49836f3b1): perf score=1.000000
I20260812 06:17:18.721302 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: FlushMRSOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.031s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1152509,"cfile_init":1,"dirs.queue_time_us":462,"dirs.run_cpu_time_us":292,"dirs.run_wall_time_us":1494,"drs_written":1,"lbm_read_time_us":41,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1515,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28,"spinlock_wait_cycles":896}
I20260812 06:17:18.722067 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling LogGCOp(ce680e7cac394f86b7d1fcb49836f3b1): free 108988502 bytes of WAL
I20260812 06:17:18.722324 31147 log_reader.cc:385] T ce680e7cac394f86b7d1fcb49836f3b1: removed 11 log segments from log reader
I20260812 06:17:18.722370 31147 log.cc:1079] T ce680e7cac394f86b7d1fcb49836f3b1 P 5b5a41849bc24164810226c43c2ce076: Deleting log segment in path: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430933609-30815-0/minicluster-data/ts-0-root/wals/ce680e7cac394f86b7d1fcb49836f3b1/wal-000000003 (ops 11-15)
I20260812 06:17:18.722401 31147 log.cc:1079] T ce680e7cac394f86b7d1fcb49836f3b1 P 5b5a41849bc24164810226c43c2ce076: Deleting log segment in path: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430933609-30815-0/minicluster-data/ts-0-root/wals/ce680e7cac394f86b7d1fcb49836f3b1/wal-000000004 (ops 16-20)
I20260812 06:17:18.722476 31147 log.cc:1079] T ce680e7cac394f86b7d1fcb49836f3b1 P 5b5a41849bc24164810226c43c2ce076: Deleting log segment in path: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430933609-30815-0/minicluster-data/ts-0-root/wals/ce680e7cac394f86b7d1fcb49836f3b1/wal-000000005 (ops 21-25)
I20260812 06:17:18.722514 31147 log.cc:1079] T ce680e7cac394f86b7d1fcb49836f3b1 P 5b5a41849bc24164810226c43c2ce076: Deleting log segment in path: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430933609-30815-0/minicluster-data/ts-0-root/wals/ce680e7cac394f86b7d1fcb49836f3b1/wal-000000006 (ops 26-30)
I20260812 06:17:18.722551 31147 log.cc:1079] T ce680e7cac394f86b7d1fcb49836f3b1 P 5b5a41849bc24164810226c43c2ce076: Deleting log segment in path: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430933609-30815-0/minicluster-data/ts-0-root/wals/ce680e7cac394f86b7d1fcb49836f3b1/wal-000000007 (ops 31-34)
I20260812 06:17:18.722589 31147 log.cc:1079] T ce680e7cac394f86b7d1fcb49836f3b1 P 5b5a41849bc24164810226c43c2ce076: Deleting log segment in path: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430933609-30815-0/minicluster-data/ts-0-root/wals/ce680e7cac394f86b7d1fcb49836f3b1/wal-000000008 (ops 35-39)
I20260812 06:17:18.722630 31147 log.cc:1079] T ce680e7cac394f86b7d1fcb49836f3b1 P 5b5a41849bc24164810226c43c2ce076: Deleting log segment in path: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430933609-30815-0/minicluster-data/ts-0-root/wals/ce680e7cac394f86b7d1fcb49836f3b1/wal-000000009 (ops 40-44)
I20260812 06:17:18.722667 31147 log.cc:1079] T ce680e7cac394f86b7d1fcb49836f3b1 P 5b5a41849bc24164810226c43c2ce076: Deleting log segment in path: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430933609-30815-0/minicluster-data/ts-0-root/wals/ce680e7cac394f86b7d1fcb49836f3b1/wal-000000010 (ops 45-49)
I20260812 06:17:18.722705 31147 log.cc:1079] T ce680e7cac394f86b7d1fcb49836f3b1 P 5b5a41849bc24164810226c43c2ce076: Deleting log segment in path: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430933609-30815-0/minicluster-data/ts-0-root/wals/ce680e7cac394f86b7d1fcb49836f3b1/wal-000000011 (ops 50-54)
I20260812 06:17:18.722743 31147 log.cc:1079] T ce680e7cac394f86b7d1fcb49836f3b1 P 5b5a41849bc24164810226c43c2ce076: Deleting log segment in path: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430933609-30815-0/minicluster-data/ts-0-root/wals/ce680e7cac394f86b7d1fcb49836f3b1/wal-000000012 (ops 55-59)
I20260812 06:17:18.722787 31147 log.cc:1079] T ce680e7cac394f86b7d1fcb49836f3b1 P 5b5a41849bc24164810226c43c2ce076: Deleting log segment in path: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430933609-30815-0/minicluster-data/ts-0-root/wals/ce680e7cac394f86b7d1fcb49836f3b1/wal-000000013 (ops 60-64)
I20260812 06:17:18.752933 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: LogGCOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.031s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:17:18.753445 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling UndoDeltaBlockGCOp(ce680e7cac394f86b7d1fcb49836f3b1): 447 bytes on disk
I20260812 06:17:18.756980 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: UndoDeltaBlockGCOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":77,"lbm_reads_lt_1ms":4}
I20260812 06:17:18.757756 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1): perf score=3.181125
I20260812 06:17:18.781181 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.019s	user 0.016s	sys 0.000s Metrics: {"bytes_written":5579537,"delete_count":0,"lbm_write_time_us":7469,"lbm_writes_lt_1ms":139,"reinsert_count":0,"update_count":680}
I20260812 06:17:18.781687 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1): perf score=1.196750
I20260812 06:17:18.794929 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.013s	user 0.009s	sys 0.004s Metrics: {"bytes_written":2625754,"delete_count":0,"lbm_write_time_us":4592,"lbm_writes_lt_1ms":67,"reinsert_count":0,"update_count":320}
I20260812 06:17:18.795548 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling MajorDeltaCompactionOp(ce680e7cac394f86b7d1fcb49836f3b1): perf score=1.000000
I20260812 06:17:19.007149 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: MajorDeltaCompactionOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.211s	user 0.157s	sys 0.052s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836341,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":2981,"lbm_read_time_us":16741,"lbm_reads_lt_1ms":674,"lbm_write_time_us":38234,"lbm_writes_lt_1ms":643,"mutex_wait_us":64,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":105,"threads_started":1,"update_count":3000}
I20260812 06:17:19.008379 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1): perf score=14.095187
I20260812 06:17:19.066730 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.058s	user 0.030s	sys 0.027s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":25902,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:19.067410 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1): perf score=2.188937
I20260812 06:17:19.083199 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.016s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6373,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:19.083762 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling MajorDeltaCompactionOp(ce680e7cac394f86b7d1fcb49836f3b1): perf score=1.000000
I20260812 06:17:19.245124 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: MajorDeltaCompactionOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.161s	user 0.128s	sys 0.027s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":239,"lbm_read_time_us":11645,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31832,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6400,"update_count":2500}
I20260812 06:17:19.245852 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1): perf score=11.118625
I20260812 06:17:19.282197 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.036s	user 0.023s	sys 0.012s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15974,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:19.282809 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1): perf score=2.188937
I20260812 06:17:19.295063 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.012s	user 0.003s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4565,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:19.295512 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling MajorDeltaCompactionOp(ce680e7cac394f86b7d1fcb49836f3b1): perf score=1.000000
I20260812 06:17:19.424166 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: MajorDeltaCompactionOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.128s	user 0.116s	sys 0.012s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631303,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":284,"lbm_read_time_us":8245,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24857,"lbm_writes_lt_1ms":443,"mutex_wait_us":43,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2048,"update_count":2000}
I20260812 06:17:19.424804 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1): perf score=10.126437
I20260812 06:17:19.472373 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.047s	user 0.023s	sys 0.013s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":17005,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:19.473074 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1): perf score=2.188937
I20260812 06:17:19.485321 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.012s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4260,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:19.485872 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling MajorDeltaCompactionOp(ce680e7cac394f86b7d1fcb49836f3b1): perf score=1.000000
I20260812 06:17:19.624715 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: MajorDeltaCompactionOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.139s	user 0.114s	sys 0.024s 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":392,"lbm_read_time_us":11529,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25800,"lbm_writes_lt_1ms":443,"mutex_wait_us":25,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":18688,"update_count":2000}
I20260812 06:17:19.625449 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1): perf score=10.126437
I20260812 06:17:19.682536 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.057s	user 0.020s	sys 0.030s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17873,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:19.683207 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1): perf score=2.188937
I20260812 06:17:19.694689 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.011s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4422,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:19.695262 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling MajorDeltaCompactionOp(ce680e7cac394f86b7d1fcb49836f3b1): perf score=1.000000
I20260812 06:17:19.864535 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: MajorDeltaCompactionOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.169s	user 0.113s	sys 0.056s 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":481,"lbm_read_time_us":13149,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27156,"lbm_writes_lt_1ms":443,"mutex_wait_us":53,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7040,"update_count":2000}
I20260812 06:17:19.865604 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1): perf score=10.126437
I20260812 06:17:19.912874 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.047s	user 0.024s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20540,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:19.913439 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1): perf score=2.188937
I20260812 06:17:19.925673 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4342,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:19.926394 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling MajorDeltaCompactionOp(ce680e7cac394f86b7d1fcb49836f3b1): perf score=1.000000
I20260812 06:17:20.059175 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: MajorDeltaCompactionOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.133s	user 0.108s	sys 0.024s 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":438,"lbm_read_time_us":8467,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26643,"lbm_writes_lt_1ms":443,"mutex_wait_us":32,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":19200,"update_count":2000}
I20260812 06:17:20.059998 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1): perf score=10.126437
I20260812 06:17:20.109766 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.050s	user 0.025s	sys 0.020s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":21055,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:20.110494 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1): perf score=2.188937
I20260812 06:17:20.128993 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.018s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5661,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:20.129674 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling FlushMRSOp(ce680e7cac394f86b7d1fcb49836f3b1): perf score=1.000000
I20260812 06:17:20.155906 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: FlushMRSOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.026s	user 0.024s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":95,"dirs.run_cpu_time_us":283,"dirs.run_wall_time_us":1682,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1488,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:20.156610 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling LogGCOp(ce680e7cac394f86b7d1fcb49836f3b1): free 115490132 bytes of WAL
I20260812 06:17:20.156869 31147 log_reader.cc:385] T ce680e7cac394f86b7d1fcb49836f3b1: removed 11 log segments from log reader
I20260812 06:17:20.156916 31147 log.cc:1079] T ce680e7cac394f86b7d1fcb49836f3b1 P 5b5a41849bc24164810226c43c2ce076: Deleting log segment in path: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430933609-30815-0/minicluster-data/ts-0-root/wals/ce680e7cac394f86b7d1fcb49836f3b1/wal-000000014 (ops 65-68)
I20260812 06:17:20.156948 31147 log.cc:1079] T ce680e7cac394f86b7d1fcb49836f3b1 P 5b5a41849bc24164810226c43c2ce076: Deleting log segment in path: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430933609-30815-0/minicluster-data/ts-0-root/wals/ce680e7cac394f86b7d1fcb49836f3b1/wal-000000015 (ops 69-73)
I20260812 06:17:20.156965 31147 log.cc:1079] T ce680e7cac394f86b7d1fcb49836f3b1 P 5b5a41849bc24164810226c43c2ce076: Deleting log segment in path: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430933609-30815-0/minicluster-data/ts-0-root/wals/ce680e7cac394f86b7d1fcb49836f3b1/wal-000000016 (ops 74-78)
I20260812 06:17:20.157009 31147 log.cc:1079] T ce680e7cac394f86b7d1fcb49836f3b1 P 5b5a41849bc24164810226c43c2ce076: Deleting log segment in path: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430933609-30815-0/minicluster-data/ts-0-root/wals/ce680e7cac394f86b7d1fcb49836f3b1/wal-000000017 (ops 79-83)
I20260812 06:17:20.157053 31147 log.cc:1079] T ce680e7cac394f86b7d1fcb49836f3b1 P 5b5a41849bc24164810226c43c2ce076: Deleting log segment in path: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430933609-30815-0/minicluster-data/ts-0-root/wals/ce680e7cac394f86b7d1fcb49836f3b1/wal-000000018 (ops 84-88)
I20260812 06:17:20.157079 31147 log.cc:1079] T ce680e7cac394f86b7d1fcb49836f3b1 P 5b5a41849bc24164810226c43c2ce076: Deleting log segment in path: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430933609-30815-0/minicluster-data/ts-0-root/wals/ce680e7cac394f86b7d1fcb49836f3b1/wal-000000019 (ops 89-93)
I20260812 06:17:20.157105 31147 log.cc:1079] T ce680e7cac394f86b7d1fcb49836f3b1 P 5b5a41849bc24164810226c43c2ce076: Deleting log segment in path: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430933609-30815-0/minicluster-data/ts-0-root/wals/ce680e7cac394f86b7d1fcb49836f3b1/wal-000000020 (ops 94-98)
I20260812 06:17:20.157145 31147 log.cc:1079] T ce680e7cac394f86b7d1fcb49836f3b1 P 5b5a41849bc24164810226c43c2ce076: Deleting log segment in path: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430933609-30815-0/minicluster-data/ts-0-root/wals/ce680e7cac394f86b7d1fcb49836f3b1/wal-000000021 (ops 99-103)
I20260812 06:17:20.157232 31147 log.cc:1079] T ce680e7cac394f86b7d1fcb49836f3b1 P 5b5a41849bc24164810226c43c2ce076: Deleting log segment in path: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430933609-30815-0/minicluster-data/ts-0-root/wals/ce680e7cac394f86b7d1fcb49836f3b1/wal-000000022 (ops 104-108)
I20260812 06:17:20.157253 31147 log.cc:1079] T ce680e7cac394f86b7d1fcb49836f3b1 P 5b5a41849bc24164810226c43c2ce076: Deleting log segment in path: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430933609-30815-0/minicluster-data/ts-0-root/wals/ce680e7cac394f86b7d1fcb49836f3b1/wal-000000023 (ops 109-113)
I20260812 06:17:20.157307 31147 log.cc:1079] T ce680e7cac394f86b7d1fcb49836f3b1 P 5b5a41849bc24164810226c43c2ce076: Deleting log segment in path: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430933609-30815-0/minicluster-data/ts-0-root/wals/ce680e7cac394f86b7d1fcb49836f3b1/wal-000000024 (ops 114-118)
I20260812 06:17:20.184322 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: LogGCOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.028s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:17:20.184871 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling UndoDeltaBlockGCOp(ce680e7cac394f86b7d1fcb49836f3b1): 448 bytes on disk
I20260812 06:17:20.185591 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: UndoDeltaBlockGCOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4}
I20260812 06:17:20.186313 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1): perf score=6.157687
I20260812 06:17:20.207962 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.021s	user 0.019s	sys 0.001s Metrics: {"bytes_written":7794837,"delete_count":0,"lbm_write_time_us":8521,"lbm_writes_lt_1ms":193,"reinsert_count":0,"update_count":950}
I20260812 06:17:20.208526 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling MajorDeltaCompactionOp(ce680e7cac394f86b7d1fcb49836f3b1): perf score=1.000000
I20260812 06:17:20.392699 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: MajorDeltaCompactionOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.184s	user 0.158s	sys 0.024s Metrics: {"cfile_cache_miss":623,"cfile_cache_miss_bytes":28426017,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":3804,"lbm_read_time_us":12587,"lbm_reads_lt_1ms":659,"lbm_write_time_us":37222,"lbm_writes_lt_1ms":633,"mutex_wait_us":1896,"peak_mem_usage":74091738,"reinsert_count":0,"spinlock_wait_cycles":4224,"thread_start_us":96,"threads_started":1,"update_count":2950}
I20260812 06:17:20.393498 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1): perf score=15.087375
I20260812 06:17:20.448328 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.055s	user 0.032s	sys 0.015s Metrics: {"bytes_written":16820148,"delete_count":0,"lbm_write_time_us":22322,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:17:20.448889 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1): perf score=2.188937
I20260812 06:17:20.460940 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.012s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4183,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:20.461472 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling MajorDeltaCompactionOp(ce680e7cac394f86b7d1fcb49836f3b1): perf score=1.000000
I20260812 06:17:20.640867 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: MajorDeltaCompactionOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.179s	user 0.126s	sys 0.035s Metrics: {"cfile_cache_miss":542,"cfile_cache_miss_bytes":25143970,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":241,"lbm_read_time_us":12891,"lbm_reads_lt_1ms":582,"lbm_write_time_us":30784,"lbm_writes_lt_1ms":553,"mutex_wait_us":19,"peak_mem_usage":63526250,"reinsert_count":0,"spinlock_wait_cycles":143104,"update_count":2550}
I20260812 06:17:20.641667 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1): perf score=14.095187
I20260812 06:17:20.709988 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.068s	user 0.034s	sys 0.019s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":26341,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:20.710661 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1): perf score=2.188937
I20260812 06:17:20.725288 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.014s	user 0.010s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5141,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:20.725816 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling MajorDeltaCompactionOp(ce680e7cac394f86b7d1fcb49836f3b1): perf score=1.000000
I20260812 06:17:20.925345 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: MajorDeltaCompactionOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.199s	user 0.139s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733726,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":947,"lbm_read_time_us":14162,"lbm_reads_lt_1ms":568,"lbm_write_time_us":34207,"lbm_writes_lt_1ms":543,"mutex_wait_us":111,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":2500}
I20260812 06:17:20.925944 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1): perf score=14.095187
I20260812 06:17:20.994251 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.068s	user 0.037s	sys 0.023s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":28935,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:17:20.994789 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1): perf score=2.188937
I20260812 06:17:21.007031 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4627,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:21.007794 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling MajorDeltaCompactionOp(ce680e7cac394f86b7d1fcb49836f3b1): perf score=1.000000
I20260812 06:17:21.194340 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: MajorDeltaCompactionOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.186s	user 0.099s	sys 0.082s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733720,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":289,"lbm_read_time_us":12694,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33769,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11776,"update_count":2500}
I20260812 06:17:21.194957 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1): perf score=14.095187
I20260812 06:17:21.257669 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.063s	user 0.046s	sys 0.008s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21632,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:21.258419 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1): perf score=2.188937
I20260812 06:17:21.269361 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4145,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:21.269879 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling MajorDeltaCompactionOp(ce680e7cac394f86b7d1fcb49836f3b1): perf score=1.000000
I20260812 06:17:21.442700 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: MajorDeltaCompactionOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.173s	user 0.118s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":163,"lbm_read_time_us":13152,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27544,"lbm_writes_lt_1ms":543,"mutex_wait_us":66,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11648,"update_count":2500}
I20260812 06:17:21.443576 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1): perf score=11.118625
I20260812 06:17:21.474686 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.031s	user 0.015s	sys 0.015s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":13247,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:21.475579 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1): perf score=2.188937
I20260812 06:17:21.498526 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.023s	user 0.010s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5575,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:21.499078 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling MajorDeltaCompactionOp(ce680e7cac394f86b7d1fcb49836f3b1): perf score=1.000000
I20260812 06:17:21.658754 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: MajorDeltaCompactionOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.160s	user 0.111s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631304,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":589,"lbm_read_time_us":9657,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24651,"lbm_writes_lt_1ms":443,"mutex_wait_us":292,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12928,"update_count":2000}
I20260812 06:17:21.659638 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1): perf score=14.095187
I20260812 06:17:21.711251 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.051s	user 0.031s	sys 0.016s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21546,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:21.711864 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1): perf score=2.188937
I20260812 06:17:21.723438 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.011s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4225,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:21.724006 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling FlushMRSOp(ce680e7cac394f86b7d1fcb49836f3b1): perf score=1.000000
I20260812 06:17:21.757120 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: FlushMRSOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.033s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1234476,"cfile_init":1,"dirs.queue_time_us":82,"dirs.run_cpu_time_us":247,"dirs.run_wall_time_us":1642,"drs_written":1,"lbm_read_time_us":72,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1731,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:17:21.757830 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling LogGCOp(ce680e7cac394f86b7d1fcb49836f3b1): free 121006604 bytes of WAL
I20260812 06:17:21.758108 31147 log_reader.cc:385] T ce680e7cac394f86b7d1fcb49836f3b1: removed 12 log segments from log reader
I20260812 06:17:21.758210 31147 log.cc:1079] T ce680e7cac394f86b7d1fcb49836f3b1 P 5b5a41849bc24164810226c43c2ce076: Deleting log segment in path: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430933609-30815-0/minicluster-data/ts-0-root/wals/ce680e7cac394f86b7d1fcb49836f3b1/wal-000000025 (ops 119-123)
I20260812 06:17:21.758258 31147 log.cc:1079] T ce680e7cac394f86b7d1fcb49836f3b1 P 5b5a41849bc24164810226c43c2ce076: Deleting log segment in path: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430933609-30815-0/minicluster-data/ts-0-root/wals/ce680e7cac394f86b7d1fcb49836f3b1/wal-000000026 (ops 124-128)
I20260812 06:17:21.758288 31147 log.cc:1079] T ce680e7cac394f86b7d1fcb49836f3b1 P 5b5a41849bc24164810226c43c2ce076: Deleting log segment in path: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430933609-30815-0/minicluster-data/ts-0-root/wals/ce680e7cac394f86b7d1fcb49836f3b1/wal-000000027 (ops 129-133)
I20260812 06:17:21.758322 31147 log.cc:1079] T ce680e7cac394f86b7d1fcb49836f3b1 P 5b5a41849bc24164810226c43c2ce076: Deleting log segment in path: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430933609-30815-0/minicluster-data/ts-0-root/wals/ce680e7cac394f86b7d1fcb49836f3b1/wal-000000028 (ops 134-138)
I20260812 06:17:21.758356 31147 log.cc:1079] T ce680e7cac394f86b7d1fcb49836f3b1 P 5b5a41849bc24164810226c43c2ce076: Deleting log segment in path: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430933609-30815-0/minicluster-data/ts-0-root/wals/ce680e7cac394f86b7d1fcb49836f3b1/wal-000000029 (ops 139-143)
I20260812 06:17:21.758387 31147 log.cc:1079] T ce680e7cac394f86b7d1fcb49836f3b1 P 5b5a41849bc24164810226c43c2ce076: Deleting log segment in path: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430933609-30815-0/minicluster-data/ts-0-root/wals/ce680e7cac394f86b7d1fcb49836f3b1/wal-000000030 (ops 144-148)
I20260812 06:17:21.758415 31147 log.cc:1079] T ce680e7cac394f86b7d1fcb49836f3b1 P 5b5a41849bc24164810226c43c2ce076: Deleting log segment in path: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430933609-30815-0/minicluster-data/ts-0-root/wals/ce680e7cac394f86b7d1fcb49836f3b1/wal-000000031 (ops 149-153)
I20260812 06:17:21.758450 31147 log.cc:1079] T ce680e7cac394f86b7d1fcb49836f3b1 P 5b5a41849bc24164810226c43c2ce076: Deleting log segment in path: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430933609-30815-0/minicluster-data/ts-0-root/wals/ce680e7cac394f86b7d1fcb49836f3b1/wal-000000032 (ops 154-158)
I20260812 06:17:21.758484 31147 log.cc:1079] T ce680e7cac394f86b7d1fcb49836f3b1 P 5b5a41849bc24164810226c43c2ce076: Deleting log segment in path: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430933609-30815-0/minicluster-data/ts-0-root/wals/ce680e7cac394f86b7d1fcb49836f3b1/wal-000000033 (ops 159-162)
I20260812 06:17:21.758519 31147 log.cc:1079] T ce680e7cac394f86b7d1fcb49836f3b1 P 5b5a41849bc24164810226c43c2ce076: Deleting log segment in path: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430933609-30815-0/minicluster-data/ts-0-root/wals/ce680e7cac394f86b7d1fcb49836f3b1/wal-000000034 (ops 163-167)
I20260812 06:17:21.758550 31147 log.cc:1079] T ce680e7cac394f86b7d1fcb49836f3b1 P 5b5a41849bc24164810226c43c2ce076: Deleting log segment in path: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430933609-30815-0/minicluster-data/ts-0-root/wals/ce680e7cac394f86b7d1fcb49836f3b1/wal-000000035 (ops 168-172)
I20260812 06:17:21.758580 31147 log.cc:1079] T ce680e7cac394f86b7d1fcb49836f3b1 P 5b5a41849bc24164810226c43c2ce076: Deleting log segment in path: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430933609-30815-0/minicluster-data/ts-0-root/wals/ce680e7cac394f86b7d1fcb49836f3b1/wal-000000036 (ops 173-177)
I20260812 06:17:21.788955 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: LogGCOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.031s	user 0.000s	sys 0.028s Metrics: {}
I20260812 06:17:21.789453 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling UndoDeltaBlockGCOp(ce680e7cac394f86b7d1fcb49836f3b1): 472 bytes on disk
I20260812 06:17:21.790256 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: UndoDeltaBlockGCOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4}
I20260812 06:17:21.791041 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1): perf score=3.181125
I20260812 06:17:21.821488 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.030s	user 0.015s	sys 0.010s Metrics: {"bytes_written":4430855,"delete_count":0,"lbm_write_time_us":7180,"lbm_writes_lt_1ms":111,"reinsert_count":0,"update_count":540}
I20260812 06:17:21.822062 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling LogGCOp(ce680e7cac394f86b7d1fcb49836f3b1): free 12018006 bytes of WAL
I20260812 06:17:21.822324 31147 log_reader.cc:385] T ce680e7cac394f86b7d1fcb49836f3b1: removed 1 log segments from log reader
I20260812 06:17:21.822396 31147 log.cc:1079] T ce680e7cac394f86b7d1fcb49836f3b1 P 5b5a41849bc24164810226c43c2ce076: Deleting log segment in path: /tmp/dist-test-taskL_b_tQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430933609-30815-0/minicluster-data/ts-0-root/wals/ce680e7cac394f86b7d1fcb49836f3b1/wal-000000037 (ops 178-182)
I20260812 06:17:21.824864 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: LogGCOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:17:21.825387 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1): perf score=2.188937
I20260812 06:17:21.837308 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":3774459,"delete_count":0,"lbm_write_time_us":4479,"lbm_writes_lt_1ms":95,"reinsert_count":0,"update_count":460}
I20260812 06:17:21.837901 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling MajorDeltaCompactionOp(ce680e7cac394f86b7d1fcb49836f3b1): perf score=1.000000
I20260812 06:17:22.094560 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: MajorDeltaCompactionOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.256s	user 0.143s	sys 0.102s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32938783,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":281,"lbm_read_time_us":15842,"lbm_reads_lt_1ms":774,"lbm_write_time_us":39110,"lbm_writes_lt_1ms":743,"mutex_wait_us":52,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":13440,"thread_start_us":87,"threads_started":1,"update_count":3500}
I20260812 06:17:22.095409 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1): perf score=18.063937
I20260812 06:17:22.153662 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.058s	user 0.028s	sys 0.024s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":25258,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:22.154541 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling MajorDeltaCompactionOp(ce680e7cac394f86b7d1fcb49836f3b1): perf score=1.000000
I20260812 06:17:22.336854 30815 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.203s	user 1.901s	sys 0.132s
I20260812 06:17:22.342523 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: MajorDeltaCompactionOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.188s	user 0.120s	sys 0.067s Metrics: {"cfile_cache_miss":531,"cfile_cache_miss_bytes":24733606,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":714,"lbm_read_time_us":13921,"lbm_reads_lt_1ms":563,"lbm_write_time_us":31452,"lbm_writes_lt_1ms":543,"mutex_wait_us":2,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:22.343468 31215 maintenance_manager.cc:419] P 5b5a41849bc24164810226c43c2ce076: Scheduling FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1): perf score=14.095187
I20260812 06:17:22.367013 30815 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.030s	user 0.003s	sys 0.000s
I20260812 06:17:22.367622 30815 tablet_server.cc:179] TabletServer@127.30.23.193:0 shutting down...
I20260812 06:17:22.391314 31147 maintenance_manager.cc:643] P 5b5a41849bc24164810226c43c2ce076: FlushDeltaMemStoresOp(ce680e7cac394f86b7d1fcb49836f3b1) complete. Timing: real 0.048s	user 0.026s	sys 0.020s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":20978,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:22.392081 30815 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:22.392335 30815 tablet_replica.cc:333] T ce680e7cac394f86b7d1fcb49836f3b1 P 5b5a41849bc24164810226c43c2ce076: stopping tablet replica
I20260812 06:17:22.392473 30815 raft_consensus.cc:2243] T ce680e7cac394f86b7d1fcb49836f3b1 P 5b5a41849bc24164810226c43c2ce076 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:22.405721 30815 raft_consensus.cc:2272] T ce680e7cac394f86b7d1fcb49836f3b1 P 5b5a41849bc24164810226c43c2ce076 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:22.410053 30815 tablet_server.cc:196] TabletServer@127.30.23.193:0 shutdown complete.
I20260812 06:17:22.413625 30815 master.cc:562] Master@127.30.23.254:44135 shutting down...
I20260812 06:17:22.417380 30815 raft_consensus.cc:2243] T 00000000000000000000000000000000 P b19827918bbe494eb905bfc94f04a503 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:22.417613 30815 raft_consensus.cc:2272] T 00000000000000000000000000000000 P b19827918bbe494eb905bfc94f04a503 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:22.417694 30815 tablet_replica.cc:333] T 00000000000000000000000000000000 P b19827918bbe494eb905bfc94f04a503: stopping tablet replica
I20260812 06:17:22.430719 30815 master.cc:584] Master@127.30.23.254:44135 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5639 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11584 ms total)

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