[==========] 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:20:21.142453  5928 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.5.202.62:45061
I20260812 06:20:21.143502  5928 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:20:21.144148  5928 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:21.150344  5933 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:20:21.150359  5936 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:20:21.150592  5928 server_base.cc:1061] running on GCE node
W20260812 06:20:21.150617  5934 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:20:21.151072  5928 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:21.151160  5928 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:20:21.151208  5928 hybrid_clock.cc:648] HybridClock initialized: now 1786515621151205 us; error 0 us; skew 500 ppm
I20260812 06:20:21.153098  5928 webserver.cc:533] Webserver started at http://127.5.202.62:45949/ using document root <none> and password file <none>
I20260812 06:20:21.153640  5928 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:21.153725  5928 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:21.154003  5928 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:21.155638  5928 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621131617-5928-0/minicluster-data/master-0-root/instance:
uuid: "848f127997374f81a4d85c624ef7b3a6"
format_stamp: "Formatted at 2026-08-12 06:20:21 on dist-test-slave-10pc"
I20260812 06:20:21.159162  5928 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.002s	sys 0.003s
I20260812 06:20:21.161293  5942 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:20:21.162279  5928 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:20:21.162425  5928 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621131617-5928-0/minicluster-data/master-0-root
uuid: "848f127997374f81a4d85c624ef7b3a6"
format_stamp: "Formatted at 2026-08-12 06:20:21 on dist-test-slave-10pc"
I20260812 06:20:21.162529  5928 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621131617-5928-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621131617-5928-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621131617-5928-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:20:21.174110  5928 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:21.174690  5928 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:20:21.174872  5928 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:21.182545  5999 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.5.202.62:45061 every 8 connection(s)
I20260812 06:20:21.182550  5928 rpc_server.cc:307] RPC server started. Bound to: 127.5.202.62:45061
I20260812 06:20:21.184998  6000 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:20:21.190569  6000 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 848f127997374f81a4d85c624ef7b3a6: Bootstrap starting.
I20260812 06:20:21.193001  6000 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 848f127997374f81a4d85c624ef7b3a6: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:21.193917  6000 log.cc:826] T 00000000000000000000000000000000 P 848f127997374f81a4d85c624ef7b3a6: Log is configured to *not* fsync() on all Append() calls
I20260812 06:20:21.195721  6000 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 848f127997374f81a4d85c624ef7b3a6: No bootstrap required, opened a new log
I20260812 06:20:21.198678  6000 raft_consensus.cc:359] T 00000000000000000000000000000000 P 848f127997374f81a4d85c624ef7b3a6 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "848f127997374f81a4d85c624ef7b3a6" member_type: VOTER }
I20260812 06:20:21.198844  6000 raft_consensus.cc:385] T 00000000000000000000000000000000 P 848f127997374f81a4d85c624ef7b3a6 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:21.198886  6000 raft_consensus.cc:740] T 00000000000000000000000000000000 P 848f127997374f81a4d85c624ef7b3a6 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 848f127997374f81a4d85c624ef7b3a6, State: Initialized, Role: FOLLOWER
I20260812 06:20:21.199492  6000 consensus_queue.cc:260] T 00000000000000000000000000000000 P 848f127997374f81a4d85c624ef7b3a6 [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: "848f127997374f81a4d85c624ef7b3a6" member_type: VOTER }
I20260812 06:20:21.199676  6000 raft_consensus.cc:399] T 00000000000000000000000000000000 P 848f127997374f81a4d85c624ef7b3a6 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:21.199756  6000 raft_consensus.cc:493] T 00000000000000000000000000000000 P 848f127997374f81a4d85c624ef7b3a6 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:21.199930  6000 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 848f127997374f81a4d85c624ef7b3a6 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:21.200804  6000 raft_consensus.cc:515] T 00000000000000000000000000000000 P 848f127997374f81a4d85c624ef7b3a6 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "848f127997374f81a4d85c624ef7b3a6" member_type: VOTER }
I20260812 06:20:21.201265  6000 leader_election.cc:304] T 00000000000000000000000000000000 P 848f127997374f81a4d85c624ef7b3a6 [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: 848f127997374f81a4d85c624ef7b3a6; no voters: 
I20260812 06:20:21.201588  6000 leader_election.cc:290] T 00000000000000000000000000000000 P 848f127997374f81a4d85c624ef7b3a6 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:21.201747  6003 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 848f127997374f81a4d85c624ef7b3a6 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:21.202000  6003 raft_consensus.cc:697] T 00000000000000000000000000000000 P 848f127997374f81a4d85c624ef7b3a6 [term 1 LEADER]: Becoming Leader. State: Replica: 848f127997374f81a4d85c624ef7b3a6, State: Running, Role: LEADER
I20260812 06:20:21.202481  6003 consensus_queue.cc:237] T 00000000000000000000000000000000 P 848f127997374f81a4d85c624ef7b3a6 [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: "848f127997374f81a4d85c624ef7b3a6" member_type: VOTER }
I20260812 06:20:21.202572  6000 sys_catalog.cc:565] T 00000000000000000000000000000000 P 848f127997374f81a4d85c624ef7b3a6 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:20:21.204495  6004 sys_catalog.cc:455] T 00000000000000000000000000000000 P 848f127997374f81a4d85c624ef7b3a6 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "848f127997374f81a4d85c624ef7b3a6" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "848f127997374f81a4d85c624ef7b3a6" member_type: VOTER } }
I20260812 06:20:21.204636  6004 sys_catalog.cc:458] T 00000000000000000000000000000000 P 848f127997374f81a4d85c624ef7b3a6 [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:21.204433  6005 sys_catalog.cc:455] T 00000000000000000000000000000000 P 848f127997374f81a4d85c624ef7b3a6 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 848f127997374f81a4d85c624ef7b3a6. Latest consensus state: current_term: 1 leader_uuid: "848f127997374f81a4d85c624ef7b3a6" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "848f127997374f81a4d85c624ef7b3a6" member_type: VOTER } }
I20260812 06:20:21.204900  6005 sys_catalog.cc:458] T 00000000000000000000000000000000 P 848f127997374f81a4d85c624ef7b3a6 [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:21.205184  5928 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:20:21.207006  6019 catalog_manager.cc:1594] T 00000000000000000000000000000000 P 848f127997374f81a4d85c624ef7b3a6: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:20:21.207072  6019 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:20:21.207155  6017 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:20:21.207916  6017 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:20:21.212261  6017 catalog_manager.cc:1383] Generated new cluster ID: 569a15e119f043de9d472f449abee406
I20260812 06:20:21.212329  6017 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:20:21.223119  6017 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:20:21.224261  6017 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:20:21.237092  6017 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 848f127997374f81a4d85c624ef7b3a6: Generated new TSK 0
I20260812 06:20:21.237870  6017 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:20:21.270151  5928 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:21.273319  6023 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:20:21.273358  6025 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:20:21.273355  6027 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:20:21.273586  5928 server_base.cc:1061] running on GCE node
I20260812 06:20:21.273878  5928 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:21.273949  5928 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:20:21.273974  5928 hybrid_clock.cc:648] HybridClock initialized: now 1786515621273973 us; error 0 us; skew 500 ppm
I20260812 06:20:21.274948  5928 webserver.cc:533] Webserver started at http://127.5.202.1:36315/ using document root <none> and password file <none>
I20260812 06:20:21.275123  5928 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:21.275193  5928 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:21.275274  5928 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:21.275713  5928 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621131617-5928-0/minicluster-data/ts-0-root/instance:
uuid: "88f46f5a7adb41b891c333a4424166d2"
format_stamp: "Formatted at 2026-08-12 06:20:21 on dist-test-slave-10pc"
I20260812 06:20:21.277647  5928 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:20:21.278775  6032 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:20:21.279078  5928 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:20:21.279156  5928 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621131617-5928-0/minicluster-data/ts-0-root
uuid: "88f46f5a7adb41b891c333a4424166d2"
format_stamp: "Formatted at 2026-08-12 06:20:21 on dist-test-slave-10pc"
I20260812 06:20:21.279247  5928 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621131617-5928-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621131617-5928-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621131617-5928-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:20:21.298118  5928 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:21.298890  5928 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:21.299445  5928 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:20:21.300329  5928 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:20:21.300381  5928 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:21.300451  5928 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:20:21.300522  5928 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:21.307554  5928 rpc_server.cc:307] RPC server started. Bound to: 127.5.202.1:44081
I20260812 06:20:21.307626  6104 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.5.202.1:44081 every 8 connection(s)
I20260812 06:20:21.322063  6105 heartbeater.cc:344] Connected to a master server at 127.5.202.62:45061
I20260812 06:20:21.322361  6105 heartbeater.cc:461] Registering TS with master...
I20260812 06:20:21.322880  6105 heartbeater.cc:507] Master 127.5.202.62:45061 requested a full tablet report, sending...
I20260812 06:20:21.324489  5959 ts_manager.cc:194] Registered new tserver with Master: 88f46f5a7adb41b891c333a4424166d2 (127.5.202.1:44081)
I20260812 06:20:21.324955  5928 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.016702341s
I20260812 06:20:21.325946  5959 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:55400
I20260812 06:20:21.334846  5959 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:55414:
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:20:21.350298  6065 tablet_service.cc:1511] Processing CreateTablet for tablet b5129ee4d3ef41409015d60ff6eb3337 (DEFAULT_TABLE table=heavy-update-compaction-test [id=ef71deeeb6e74e4981ec56b11c616796]), partition=
I20260812 06:20:21.350808  6065 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet b5129ee4d3ef41409015d60ff6eb3337. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:20:21.353120  6118 tablet_bootstrap.cc:492] T b5129ee4d3ef41409015d60ff6eb3337 P 88f46f5a7adb41b891c333a4424166d2: Bootstrap starting.
I20260812 06:20:21.354264  6118 tablet_bootstrap.cc:654] T b5129ee4d3ef41409015d60ff6eb3337 P 88f46f5a7adb41b891c333a4424166d2: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:21.356038  6118 tablet_bootstrap.cc:492] T b5129ee4d3ef41409015d60ff6eb3337 P 88f46f5a7adb41b891c333a4424166d2: No bootstrap required, opened a new log
I20260812 06:20:21.356155  6118 ts_tablet_manager.cc:1403] T b5129ee4d3ef41409015d60ff6eb3337 P 88f46f5a7adb41b891c333a4424166d2: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:20:21.356824  6118 raft_consensus.cc:359] T b5129ee4d3ef41409015d60ff6eb3337 P 88f46f5a7adb41b891c333a4424166d2 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "88f46f5a7adb41b891c333a4424166d2" member_type: VOTER last_known_addr { host: "127.5.202.1" port: 44081 } }
I20260812 06:20:21.356962  6118 raft_consensus.cc:385] T b5129ee4d3ef41409015d60ff6eb3337 P 88f46f5a7adb41b891c333a4424166d2 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:21.357002  6118 raft_consensus.cc:740] T b5129ee4d3ef41409015d60ff6eb3337 P 88f46f5a7adb41b891c333a4424166d2 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 88f46f5a7adb41b891c333a4424166d2, State: Initialized, Role: FOLLOWER
I20260812 06:20:21.357146  6118 consensus_queue.cc:260] T b5129ee4d3ef41409015d60ff6eb3337 P 88f46f5a7adb41b891c333a4424166d2 [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: "88f46f5a7adb41b891c333a4424166d2" member_type: VOTER last_known_addr { host: "127.5.202.1" port: 44081 } }
I20260812 06:20:21.357260  6118 raft_consensus.cc:399] T b5129ee4d3ef41409015d60ff6eb3337 P 88f46f5a7adb41b891c333a4424166d2 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:21.357366  6118 raft_consensus.cc:493] T b5129ee4d3ef41409015d60ff6eb3337 P 88f46f5a7adb41b891c333a4424166d2 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:21.357432  6118 raft_consensus.cc:3060] T b5129ee4d3ef41409015d60ff6eb3337 P 88f46f5a7adb41b891c333a4424166d2 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:21.358417  6118 raft_consensus.cc:515] T b5129ee4d3ef41409015d60ff6eb3337 P 88f46f5a7adb41b891c333a4424166d2 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "88f46f5a7adb41b891c333a4424166d2" member_type: VOTER last_known_addr { host: "127.5.202.1" port: 44081 } }
I20260812 06:20:21.358572  6118 leader_election.cc:304] T b5129ee4d3ef41409015d60ff6eb3337 P 88f46f5a7adb41b891c333a4424166d2 [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: 88f46f5a7adb41b891c333a4424166d2; no voters: 
I20260812 06:20:21.358791  6118 leader_election.cc:290] T b5129ee4d3ef41409015d60ff6eb3337 P 88f46f5a7adb41b891c333a4424166d2 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:21.358946  6120 raft_consensus.cc:2804] T b5129ee4d3ef41409015d60ff6eb3337 P 88f46f5a7adb41b891c333a4424166d2 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:21.359222  6120 raft_consensus.cc:697] T b5129ee4d3ef41409015d60ff6eb3337 P 88f46f5a7adb41b891c333a4424166d2 [term 1 LEADER]: Becoming Leader. State: Replica: 88f46f5a7adb41b891c333a4424166d2, State: Running, Role: LEADER
I20260812 06:20:21.359238  6118 ts_tablet_manager.cc:1434] T b5129ee4d3ef41409015d60ff6eb3337 P 88f46f5a7adb41b891c333a4424166d2: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:20:21.359602  6105 heartbeater.cc:499] Master 127.5.202.62:45061 was elected leader, sending a full tablet report...
I20260812 06:20:21.359694  6120 consensus_queue.cc:237] T b5129ee4d3ef41409015d60ff6eb3337 P 88f46f5a7adb41b891c333a4424166d2 [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: "88f46f5a7adb41b891c333a4424166d2" member_type: VOTER last_known_addr { host: "127.5.202.1" port: 44081 } }
I20260812 06:20:21.362668  5959 catalog_manager.cc:5719] T b5129ee4d3ef41409015d60ff6eb3337 P 88f46f5a7adb41b891c333a4424166d2 reported cstate change: term changed from 0 to 1, leader changed from <none> to 88f46f5a7adb41b891c333a4424166d2 (127.5.202.1). New cstate: current_term: 1 leader_uuid: "88f46f5a7adb41b891c333a4424166d2" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "88f46f5a7adb41b891c333a4424166d2" member_type: VOTER last_known_addr { host: "127.5.202.1" port: 44081 } health_report { overall_health: HEALTHY } } }
I20260812 06:20:21.426466  5928 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.054s	user 0.015s	sys 0.008s
I20260812 06:20:21.558755  6106 maintenance_manager.cc:419] P 88f46f5a7adb41b891c333a4424166d2: Scheduling FlushMRSOp(b5129ee4d3ef41409015d60ff6eb3337): perf score=19.054940
I20260812 06:20:21.743552  6039 maintenance_manager.cc:643] P 88f46f5a7adb41b891c333a4424166d2: FlushMRSOp(b5129ee4d3ef41409015d60ff6eb3337) complete. Timing: real 0.184s	user 0.140s	sys 0.040s Metrics: {"bytes_written":12307490,"cfile_init":1,"compiler_manager_pool.queue_time_us":183,"delete_count":0,"dirs.queue_time_us":66,"dirs.run_cpu_time_us":220,"dirs.run_wall_time_us":888,"drs_written":1,"lbm_read_time_us":112,"lbm_reads_lt_1ms":4,"lbm_write_time_us":47288,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":117,"threads_started":1,"update_count":1500}
I20260812 06:20:21.744776  6106 maintenance_manager.cc:419] P 88f46f5a7adb41b891c333a4424166d2: Scheduling LogGCOp(b5129ee4d3ef41409015d60ff6eb3337): free 20743880 bytes of WAL
I20260812 06:20:21.745108  6039 log_reader.cc:385] T b5129ee4d3ef41409015d60ff6eb3337: removed 2 log segments from log reader
I20260812 06:20:21.745198  6039 log.cc:1079] T b5129ee4d3ef41409015d60ff6eb3337 P 88f46f5a7adb41b891c333a4424166d2: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/b5129ee4d3ef41409015d60ff6eb3337/wal-000000001 (ops 1-6)
I20260812 06:20:21.745298  6039 log.cc:1079] T b5129ee4d3ef41409015d60ff6eb3337 P 88f46f5a7adb41b891c333a4424166d2: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/b5129ee4d3ef41409015d60ff6eb3337/wal-000000002 (ops 7-11)
I20260812 06:20:21.750216  6039 maintenance_manager.cc:643] P 88f46f5a7adb41b891c333a4424166d2: LogGCOp(b5129ee4d3ef41409015d60ff6eb3337) complete. Timing: real 0.005s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:20:21.750774  6106 maintenance_manager.cc:419] P 88f46f5a7adb41b891c333a4424166d2: Scheduling FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337): perf score=2.188937
I20260812 06:20:21.769122  6039 maintenance_manager.cc:643] P 88f46f5a7adb41b891c333a4424166d2: FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337) complete. Timing: real 0.018s	user 0.008s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6186,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:21.769660  6106 maintenance_manager.cc:419] P 88f46f5a7adb41b891c333a4424166d2: Scheduling UndoDeltaBlockGCOp(b5129ee4d3ef41409015d60ff6eb3337): 16411394 bytes on disk
I20260812 06:20:21.770355  6039 maintenance_manager.cc:643] P 88f46f5a7adb41b891c333a4424166d2: UndoDeltaBlockGCOp(b5129ee4d3ef41409015d60ff6eb3337) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4}
I20260812 06:20:21.770793  6106 maintenance_manager.cc:419] P 88f46f5a7adb41b891c333a4424166d2: Scheduling MajorDeltaCompactionOp(b5129ee4d3ef41409015d60ff6eb3337): perf score=1.000000
I20260812 06:20:21.925444  6039 maintenance_manager.cc:643] P 88f46f5a7adb41b891c333a4424166d2: MajorDeltaCompactionOp(b5129ee4d3ef41409015d60ff6eb3337) complete. Timing: real 0.155s	user 0.131s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":923,"lbm_read_time_us":8693,"lbm_reads_lt_1ms":460,"lbm_write_time_us":26156,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2560,"thread_start_us":414,"threads_started":5,"update_count":2000}
I20260812 06:20:21.926047  6106 maintenance_manager.cc:419] P 88f46f5a7adb41b891c333a4424166d2: Scheduling FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337): perf score=10.126437
I20260812 06:20:21.962669  6039 maintenance_manager.cc:643] P 88f46f5a7adb41b891c333a4424166d2: FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337) complete. Timing: real 0.036s	user 0.033s	sys 0.001s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":15832,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:21.963215  6106 maintenance_manager.cc:419] P 88f46f5a7adb41b891c333a4424166d2: Scheduling FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337): perf score=2.188937
I20260812 06:20:21.974310  6039 maintenance_manager.cc:643] P 88f46f5a7adb41b891c333a4424166d2: FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337) complete. Timing: real 0.011s	user 0.004s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4190,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:21.974928  6106 maintenance_manager.cc:419] P 88f46f5a7adb41b891c333a4424166d2: Scheduling MajorDeltaCompactionOp(b5129ee4d3ef41409015d60ff6eb3337): perf score=1.000000
I20260812 06:20:22.103394  6039 maintenance_manager.cc:643] P 88f46f5a7adb41b891c333a4424166d2: MajorDeltaCompactionOp(b5129ee4d3ef41409015d60ff6eb3337) complete. Timing: real 0.128s	user 0.116s	sys 0.012s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":260,"lbm_read_time_us":7620,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26392,"lbm_writes_lt_1ms":443,"mutex_wait_us":63,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11520,"update_count":2000}
I20260812 06:20:22.104031  6106 maintenance_manager.cc:419] P 88f46f5a7adb41b891c333a4424166d2: Scheduling FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337): perf score=10.126437
I20260812 06:20:22.150384  6039 maintenance_manager.cc:643] P 88f46f5a7adb41b891c333a4424166d2: FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337) complete. Timing: real 0.046s	user 0.037s	sys 0.000s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16859,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:22.150879  6106 maintenance_manager.cc:419] P 88f46f5a7adb41b891c333a4424166d2: Scheduling FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337): perf score=2.188937
I20260812 06:20:22.161615  6039 maintenance_manager.cc:643] P 88f46f5a7adb41b891c333a4424166d2: FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4056,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:22.162251  6106 maintenance_manager.cc:419] P 88f46f5a7adb41b891c333a4424166d2: Scheduling MajorDeltaCompactionOp(b5129ee4d3ef41409015d60ff6eb3337): perf score=1.000000
I20260812 06:20:22.282037  6039 maintenance_manager.cc:643] P 88f46f5a7adb41b891c333a4424166d2: MajorDeltaCompactionOp(b5129ee4d3ef41409015d60ff6eb3337) complete. Timing: real 0.119s	user 0.087s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672275,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":614,"lbm_read_time_us":8204,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23238,"lbm_writes_lt_1ms":443,"mutex_wait_us":278,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":53504,"update_count":2000}
I20260812 06:20:22.282635  6106 maintenance_manager.cc:419] P 88f46f5a7adb41b891c333a4424166d2: Scheduling FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337): perf score=10.126437
I20260812 06:20:22.328438  6039 maintenance_manager.cc:643] P 88f46f5a7adb41b891c333a4424166d2: FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337) complete. Timing: real 0.046s	user 0.022s	sys 0.019s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15083,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:22.329023  6106 maintenance_manager.cc:419] P 88f46f5a7adb41b891c333a4424166d2: Scheduling FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337): perf score=2.188937
I20260812 06:20:22.339711  6039 maintenance_manager.cc:643] P 88f46f5a7adb41b891c333a4424166d2: FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4197,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:22.340195  6106 maintenance_manager.cc:419] P 88f46f5a7adb41b891c333a4424166d2: Scheduling MajorDeltaCompactionOp(b5129ee4d3ef41409015d60ff6eb3337): perf score=1.000000
I20260812 06:20:22.496577  6039 maintenance_manager.cc:643] P 88f46f5a7adb41b891c333a4424166d2: MajorDeltaCompactionOp(b5129ee4d3ef41409015d60ff6eb3337) complete. Timing: real 0.156s	user 0.086s	sys 0.070s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":334,"lbm_read_time_us":12317,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26396,"lbm_writes_lt_1ms":443,"mutex_wait_us":63,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:20:22.497299  6106 maintenance_manager.cc:419] P 88f46f5a7adb41b891c333a4424166d2: Scheduling FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337): perf score=10.126437
I20260812 06:20:22.542379  6039 maintenance_manager.cc:643] P 88f46f5a7adb41b891c333a4424166d2: FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337) complete. Timing: real 0.045s	user 0.013s	sys 0.019s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":15243,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:22.542819  6106 maintenance_manager.cc:419] P 88f46f5a7adb41b891c333a4424166d2: Scheduling FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337): perf score=2.188937
I20260812 06:20:22.553978  6039 maintenance_manager.cc:643] P 88f46f5a7adb41b891c333a4424166d2: FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337) complete. Timing: real 0.011s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4132,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:22.554643  6106 maintenance_manager.cc:419] P 88f46f5a7adb41b891c333a4424166d2: Scheduling MajorDeltaCompactionOp(b5129ee4d3ef41409015d60ff6eb3337): perf score=1.000000
I20260812 06:20:22.680959  6039 maintenance_manager.cc:643] P 88f46f5a7adb41b891c333a4424166d2: MajorDeltaCompactionOp(b5129ee4d3ef41409015d60ff6eb3337) complete. Timing: real 0.126s	user 0.088s	sys 0.037s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672280,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":278,"lbm_read_time_us":8649,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23459,"lbm_writes_lt_1ms":443,"mutex_wait_us":20,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9984,"update_count":2000}
I20260812 06:20:22.681603  6106 maintenance_manager.cc:419] P 88f46f5a7adb41b891c333a4424166d2: Scheduling FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337): perf score=10.126437
I20260812 06:20:22.723067  6039 maintenance_manager.cc:643] P 88f46f5a7adb41b891c333a4424166d2: FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337) complete. Timing: real 0.041s	user 0.020s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15523,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:22.723587  6106 maintenance_manager.cc:419] P 88f46f5a7adb41b891c333a4424166d2: Scheduling FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337): perf score=2.188937
I20260812 06:20:22.735266  6039 maintenance_manager.cc:643] P 88f46f5a7adb41b891c333a4424166d2: FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4346,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:22.735841  6106 maintenance_manager.cc:419] P 88f46f5a7adb41b891c333a4424166d2: Scheduling MajorDeltaCompactionOp(b5129ee4d3ef41409015d60ff6eb3337): perf score=1.000000
I20260812 06:20:22.864554  6039 maintenance_manager.cc:643] P 88f46f5a7adb41b891c333a4424166d2: MajorDeltaCompactionOp(b5129ee4d3ef41409015d60ff6eb3337) complete. Timing: real 0.128s	user 0.109s	sys 0.019s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":552,"lbm_read_time_us":9315,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26528,"lbm_writes_lt_1ms":443,"mutex_wait_us":72,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:20:22.865200  6106 maintenance_manager.cc:419] P 88f46f5a7adb41b891c333a4424166d2: Scheduling FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337): perf score=10.126437
I20260812 06:20:22.917248  6039 maintenance_manager.cc:643] P 88f46f5a7adb41b891c333a4424166d2: FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337) complete. Timing: real 0.052s	user 0.023s	sys 0.025s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":18292,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:22.917743  6106 maintenance_manager.cc:419] P 88f46f5a7adb41b891c333a4424166d2: Scheduling FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337): perf score=2.188937
I20260812 06:20:22.928325  6039 maintenance_manager.cc:643] P 88f46f5a7adb41b891c333a4424166d2: FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4319,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:22.928784  6106 maintenance_manager.cc:419] P 88f46f5a7adb41b891c333a4424166d2: Scheduling FlushMRSOp(b5129ee4d3ef41409015d60ff6eb3337): perf score=1.000000
I20260812 06:20:22.971882  6039 maintenance_manager.cc:643] P 88f46f5a7adb41b891c333a4424166d2: FlushMRSOp(b5129ee4d3ef41409015d60ff6eb3337) complete. Timing: real 0.043s	user 0.029s	sys 0.003s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":76,"dirs.run_cpu_time_us":237,"dirs.run_wall_time_us":1361,"drs_written":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1465,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:20:22.972828  6106 maintenance_manager.cc:419] P 88f46f5a7adb41b891c333a4424166d2: Scheduling LogGCOp(b5129ee4d3ef41409015d60ff6eb3337): free 112692367 bytes of WAL
I20260812 06:20:22.973122  6039 log_reader.cc:385] T b5129ee4d3ef41409015d60ff6eb3337: removed 11 log segments from log reader
I20260812 06:20:22.973218  6039 log.cc:1079] T b5129ee4d3ef41409015d60ff6eb3337 P 88f46f5a7adb41b891c333a4424166d2: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/b5129ee4d3ef41409015d60ff6eb3337/wal-000000003 (ops 12-16)
I20260812 06:20:22.973273  6039 log.cc:1079] T b5129ee4d3ef41409015d60ff6eb3337 P 88f46f5a7adb41b891c333a4424166d2: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/b5129ee4d3ef41409015d60ff6eb3337/wal-000000004 (ops 17-21)
I20260812 06:20:22.973330  6039 log.cc:1079] T b5129ee4d3ef41409015d60ff6eb3337 P 88f46f5a7adb41b891c333a4424166d2: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/b5129ee4d3ef41409015d60ff6eb3337/wal-000000005 (ops 22-26)
I20260812 06:20:22.973371  6039 log.cc:1079] T b5129ee4d3ef41409015d60ff6eb3337 P 88f46f5a7adb41b891c333a4424166d2: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/b5129ee4d3ef41409015d60ff6eb3337/wal-000000006 (ops 27-31)
I20260812 06:20:22.973407  6039 log.cc:1079] T b5129ee4d3ef41409015d60ff6eb3337 P 88f46f5a7adb41b891c333a4424166d2: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/b5129ee4d3ef41409015d60ff6eb3337/wal-000000007 (ops 32-36)
I20260812 06:20:22.973445  6039 log.cc:1079] T b5129ee4d3ef41409015d60ff6eb3337 P 88f46f5a7adb41b891c333a4424166d2: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/b5129ee4d3ef41409015d60ff6eb3337/wal-000000008 (ops 37-41)
I20260812 06:20:22.973475  6039 log.cc:1079] T b5129ee4d3ef41409015d60ff6eb3337 P 88f46f5a7adb41b891c333a4424166d2: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/b5129ee4d3ef41409015d60ff6eb3337/wal-000000009 (ops 42-46)
I20260812 06:20:22.973507  6039 log.cc:1079] T b5129ee4d3ef41409015d60ff6eb3337 P 88f46f5a7adb41b891c333a4424166d2: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/b5129ee4d3ef41409015d60ff6eb3337/wal-000000010 (ops 47-51)
I20260812 06:20:22.973538  6039 log.cc:1079] T b5129ee4d3ef41409015d60ff6eb3337 P 88f46f5a7adb41b891c333a4424166d2: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/b5129ee4d3ef41409015d60ff6eb3337/wal-000000011 (ops 52-56)
I20260812 06:20:22.973575  6039 log.cc:1079] T b5129ee4d3ef41409015d60ff6eb3337 P 88f46f5a7adb41b891c333a4424166d2: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/b5129ee4d3ef41409015d60ff6eb3337/wal-000000012 (ops 57-61)
I20260812 06:20:22.973616  6039 log.cc:1079] T b5129ee4d3ef41409015d60ff6eb3337 P 88f46f5a7adb41b891c333a4424166d2: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/b5129ee4d3ef41409015d60ff6eb3337/wal-000000013 (ops 62-66)
I20260812 06:20:22.998042  6039 maintenance_manager.cc:643] P 88f46f5a7adb41b891c333a4424166d2: LogGCOp(b5129ee4d3ef41409015d60ff6eb3337) complete. Timing: real 0.025s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:20:22.998675  6106 maintenance_manager.cc:419] P 88f46f5a7adb41b891c333a4424166d2: Scheduling FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337): perf score=2.188937
I20260812 06:20:23.017354  6039 maintenance_manager.cc:643] P 88f46f5a7adb41b891c333a4424166d2: FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337) complete. Timing: real 0.018s	user 0.012s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5468,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:23.017817  6106 maintenance_manager.cc:419] P 88f46f5a7adb41b891c333a4424166d2: Scheduling FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337): perf score=2.188937
I20260812 06:20:23.028566  6039 maintenance_manager.cc:643] P 88f46f5a7adb41b891c333a4424166d2: FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4082,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:23.029000  6106 maintenance_manager.cc:419] P 88f46f5a7adb41b891c333a4424166d2: Scheduling MajorDeltaCompactionOp(b5129ee4d3ef41409015d60ff6eb3337): perf score=1.000000
I20260812 06:20:23.237634  6039 maintenance_manager.cc:643] P 88f46f5a7adb41b891c333a4424166d2: MajorDeltaCompactionOp(b5129ee4d3ef41409015d60ff6eb3337) complete. Timing: real 0.208s	user 0.133s	sys 0.072s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877338,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":7099,"lbm_read_time_us":14787,"lbm_reads_lt_1ms":674,"lbm_write_time_us":32759,"lbm_writes_lt_1ms":643,"mutex_wait_us":3195,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":18176,"thread_start_us":107,"threads_started":1,"update_count":3000}
I20260812 06:20:23.238340  6106 maintenance_manager.cc:419] P 88f46f5a7adb41b891c333a4424166d2: Scheduling UndoDeltaBlockGCOp(b5129ee4d3ef41409015d60ff6eb3337): 447 bytes on disk
I20260812 06:20:23.239199  6039 maintenance_manager.cc:643] P 88f46f5a7adb41b891c333a4424166d2: UndoDeltaBlockGCOp(b5129ee4d3ef41409015d60ff6eb3337) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":81,"lbm_reads_lt_1ms":4}
I20260812 06:20:23.239707  6106 maintenance_manager.cc:419] P 88f46f5a7adb41b891c333a4424166d2: Scheduling FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337): perf score=14.095187
I20260812 06:20:23.300943  6039 maintenance_manager.cc:643] P 88f46f5a7adb41b891c333a4424166d2: FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337) complete. Timing: real 0.061s	user 0.028s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21768,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:23.301481  6106 maintenance_manager.cc:419] P 88f46f5a7adb41b891c333a4424166d2: Scheduling FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337): perf score=2.188937
I20260812 06:20:23.312296  6039 maintenance_manager.cc:643] P 88f46f5a7adb41b891c333a4424166d2: FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4179,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:23.312783  6106 maintenance_manager.cc:419] P 88f46f5a7adb41b891c333a4424166d2: Scheduling MajorDeltaCompactionOp(b5129ee4d3ef41409015d60ff6eb3337): perf score=1.000000
I20260812 06:20:23.493611  6039 maintenance_manager.cc:643] P 88f46f5a7adb41b891c333a4424166d2: MajorDeltaCompactionOp(b5129ee4d3ef41409015d60ff6eb3337) complete. Timing: real 0.181s	user 0.118s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":616,"lbm_read_time_us":12447,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32820,"lbm_writes_lt_1ms":543,"mutex_wait_us":313,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":16768,"update_count":2500}
I20260812 06:20:23.494175  6106 maintenance_manager.cc:419] P 88f46f5a7adb41b891c333a4424166d2: Scheduling FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337): perf score=14.095187
I20260812 06:20:23.562036  6039 maintenance_manager.cc:643] P 88f46f5a7adb41b891c333a4424166d2: FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337) complete. Timing: real 0.068s	user 0.043s	sys 0.023s Metrics: {"bytes_written":16409911,"delete_count":0,"lbm_write_time_us":29943,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:20:23.562580  6106 maintenance_manager.cc:419] P 88f46f5a7adb41b891c333a4424166d2: Scheduling FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337): perf score=2.188937
I20260812 06:20:23.573381  6039 maintenance_manager.cc:643] P 88f46f5a7adb41b891c333a4424166d2: FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4240,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:23.574048  6106 maintenance_manager.cc:419] P 88f46f5a7adb41b891c333a4424166d2: Scheduling MajorDeltaCompactionOp(b5129ee4d3ef41409015d60ff6eb3337): perf score=1.000000
I20260812 06:20:23.768992  6039 maintenance_manager.cc:643] P 88f46f5a7adb41b891c333a4424166d2: MajorDeltaCompactionOp(b5129ee4d3ef41409015d60ff6eb3337) complete. Timing: real 0.195s	user 0.132s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774698,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":205,"lbm_read_time_us":14155,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31966,"lbm_writes_lt_1ms":543,"mutex_wait_us":42,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13312,"update_count":2500}
I20260812 06:20:23.769644  6106 maintenance_manager.cc:419] P 88f46f5a7adb41b891c333a4424166d2: Scheduling FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337): perf score=14.095187
I20260812 06:20:23.830406  6039 maintenance_manager.cc:643] P 88f46f5a7adb41b891c333a4424166d2: FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337) complete. Timing: real 0.061s	user 0.026s	sys 0.027s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20675,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:23.831001  6106 maintenance_manager.cc:419] P 88f46f5a7adb41b891c333a4424166d2: Scheduling FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337): perf score=2.188937
I20260812 06:20:23.847743  6039 maintenance_manager.cc:643] P 88f46f5a7adb41b891c333a4424166d2: FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337) complete. Timing: real 0.017s	user 0.003s	sys 0.011s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6347,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:23.848284  6106 maintenance_manager.cc:419] P 88f46f5a7adb41b891c333a4424166d2: Scheduling MajorDeltaCompactionOp(b5129ee4d3ef41409015d60ff6eb3337): perf score=1.000000
I20260812 06:20:24.018569  6039 maintenance_manager.cc:643] P 88f46f5a7adb41b891c333a4424166d2: MajorDeltaCompactionOp(b5129ee4d3ef41409015d60ff6eb3337) complete. Timing: real 0.170s	user 0.113s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":90,"lbm_read_time_us":12351,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30179,"lbm_writes_lt_1ms":543,"mutex_wait_us":47,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10752,"update_count":2500}
I20260812 06:20:24.019496  6106 maintenance_manager.cc:419] P 88f46f5a7adb41b891c333a4424166d2: Scheduling FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337): perf score=10.126437
I20260812 06:20:24.053449  6039 maintenance_manager.cc:643] P 88f46f5a7adb41b891c333a4424166d2: FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337) complete. Timing: real 0.034s	user 0.017s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14779,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:24.054076  6106 maintenance_manager.cc:419] P 88f46f5a7adb41b891c333a4424166d2: Scheduling FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337): perf score=2.188937
I20260812 06:20:24.068262  6039 maintenance_manager.cc:643] P 88f46f5a7adb41b891c333a4424166d2: FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5102,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:24.068776  6106 maintenance_manager.cc:419] P 88f46f5a7adb41b891c333a4424166d2: Scheduling MajorDeltaCompactionOp(b5129ee4d3ef41409015d60ff6eb3337): perf score=1.000000
I20260812 06:20:24.203703  6039 maintenance_manager.cc:643] P 88f46f5a7adb41b891c333a4424166d2: MajorDeltaCompactionOp(b5129ee4d3ef41409015d60ff6eb3337) complete. Timing: real 0.135s	user 0.112s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":681,"lbm_read_time_us":8347,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24843,"lbm_writes_lt_1ms":443,"mutex_wait_us":83,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7168,"update_count":2000}
I20260812 06:20:24.204970  6106 maintenance_manager.cc:419] P 88f46f5a7adb41b891c333a4424166d2: Scheduling FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337): perf score=10.126437
I20260812 06:20:24.245538  6039 maintenance_manager.cc:643] P 88f46f5a7adb41b891c333a4424166d2: FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337) complete. Timing: real 0.040s	user 0.024s	sys 0.008s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":14151,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:24.248771  6106 maintenance_manager.cc:419] P 88f46f5a7adb41b891c333a4424166d2: Scheduling FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337): perf score=2.188937
I20260812 06:20:24.260313  6039 maintenance_manager.cc:643] P 88f46f5a7adb41b891c333a4424166d2: FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337) complete. Timing: real 0.011s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3879,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:24.260890  6106 maintenance_manager.cc:419] P 88f46f5a7adb41b891c333a4424166d2: Scheduling MajorDeltaCompactionOp(b5129ee4d3ef41409015d60ff6eb3337): perf score=1.000000
I20260812 06:20:24.388952  6039 maintenance_manager.cc:643] P 88f46f5a7adb41b891c333a4424166d2: MajorDeltaCompactionOp(b5129ee4d3ef41409015d60ff6eb3337) complete. Timing: real 0.128s	user 0.110s	sys 0.017s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672280,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1266,"lbm_read_time_us":8062,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24813,"lbm_writes_lt_1ms":443,"mutex_wait_us":402,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3072,"update_count":2000}
I20260812 06:20:24.389591  6106 maintenance_manager.cc:419] P 88f46f5a7adb41b891c333a4424166d2: Scheduling FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337): perf score=10.126437
I20260812 06:20:24.427078  6039 maintenance_manager.cc:643] P 88f46f5a7adb41b891c333a4424166d2: FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337) complete. Timing: real 0.037s	user 0.011s	sys 0.021s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":14568,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:24.427846  6106 maintenance_manager.cc:419] P 88f46f5a7adb41b891c333a4424166d2: Scheduling FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337): perf score=2.188937
I20260812 06:20:24.439088  6039 maintenance_manager.cc:643] P 88f46f5a7adb41b891c333a4424166d2: FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3996,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:24.439571  6106 maintenance_manager.cc:419] P 88f46f5a7adb41b891c333a4424166d2: Scheduling FlushMRSOp(b5129ee4d3ef41409015d60ff6eb3337): perf score=1.000000
I20260812 06:20:24.466356  6039 maintenance_manager.cc:643] P 88f46f5a7adb41b891c333a4424166d2: FlushMRSOp(b5129ee4d3ef41409015d60ff6eb3337) complete. Timing: real 0.027s	user 0.020s	sys 0.004s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":67,"dirs.run_cpu_time_us":215,"dirs.run_wall_time_us":1618,"drs_written":1,"lbm_read_time_us":94,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1486,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:20:24.467204  6106 maintenance_manager.cc:419] P 88f46f5a7adb41b891c333a4424166d2: Scheduling LogGCOp(b5129ee4d3ef41409015d60ff6eb3337): free 120553380 bytes of WAL
I20260812 06:20:24.467483  6039 log_reader.cc:385] T b5129ee4d3ef41409015d60ff6eb3337: removed 12 log segments from log reader
I20260812 06:20:24.467549  6039 log.cc:1079] T b5129ee4d3ef41409015d60ff6eb3337 P 88f46f5a7adb41b891c333a4424166d2: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/b5129ee4d3ef41409015d60ff6eb3337/wal-000000014 (ops 67-70)
I20260812 06:20:24.467587  6039 log.cc:1079] T b5129ee4d3ef41409015d60ff6eb3337 P 88f46f5a7adb41b891c333a4424166d2: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/b5129ee4d3ef41409015d60ff6eb3337/wal-000000015 (ops 71-75)
I20260812 06:20:24.467617  6039 log.cc:1079] T b5129ee4d3ef41409015d60ff6eb3337 P 88f46f5a7adb41b891c333a4424166d2: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/b5129ee4d3ef41409015d60ff6eb3337/wal-000000016 (ops 76-80)
I20260812 06:20:24.467654  6039 log.cc:1079] T b5129ee4d3ef41409015d60ff6eb3337 P 88f46f5a7adb41b891c333a4424166d2: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/b5129ee4d3ef41409015d60ff6eb3337/wal-000000017 (ops 81-85)
I20260812 06:20:24.467679  6039 log.cc:1079] T b5129ee4d3ef41409015d60ff6eb3337 P 88f46f5a7adb41b891c333a4424166d2: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/b5129ee4d3ef41409015d60ff6eb3337/wal-000000018 (ops 86-90)
I20260812 06:20:24.467710  6039 log.cc:1079] T b5129ee4d3ef41409015d60ff6eb3337 P 88f46f5a7adb41b891c333a4424166d2: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/b5129ee4d3ef41409015d60ff6eb3337/wal-000000019 (ops 91-95)
I20260812 06:20:24.467736  6039 log.cc:1079] T b5129ee4d3ef41409015d60ff6eb3337 P 88f46f5a7adb41b891c333a4424166d2: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/b5129ee4d3ef41409015d60ff6eb3337/wal-000000020 (ops 96-100)
I20260812 06:20:24.467765  6039 log.cc:1079] T b5129ee4d3ef41409015d60ff6eb3337 P 88f46f5a7adb41b891c333a4424166d2: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/b5129ee4d3ef41409015d60ff6eb3337/wal-000000021 (ops 101-105)
I20260812 06:20:24.467793  6039 log.cc:1079] T b5129ee4d3ef41409015d60ff6eb3337 P 88f46f5a7adb41b891c333a4424166d2: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/b5129ee4d3ef41409015d60ff6eb3337/wal-000000022 (ops 106-110)
I20260812 06:20:24.467828  6039 log.cc:1079] T b5129ee4d3ef41409015d60ff6eb3337 P 88f46f5a7adb41b891c333a4424166d2: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/b5129ee4d3ef41409015d60ff6eb3337/wal-000000023 (ops 111-114)
I20260812 06:20:24.467859  6039 log.cc:1079] T b5129ee4d3ef41409015d60ff6eb3337 P 88f46f5a7adb41b891c333a4424166d2: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/b5129ee4d3ef41409015d60ff6eb3337/wal-000000024 (ops 115-119)
I20260812 06:20:24.467885  6039 log.cc:1079] T b5129ee4d3ef41409015d60ff6eb3337 P 88f46f5a7adb41b891c333a4424166d2: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/b5129ee4d3ef41409015d60ff6eb3337/wal-000000025 (ops 120-124)
I20260812 06:20:24.496838  6039 maintenance_manager.cc:643] P 88f46f5a7adb41b891c333a4424166d2: LogGCOp(b5129ee4d3ef41409015d60ff6eb3337) complete. Timing: real 0.029s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:20:24.497423  6106 maintenance_manager.cc:419] P 88f46f5a7adb41b891c333a4424166d2: Scheduling FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337): perf score=2.188937
I20260812 06:20:24.521286  6039 maintenance_manager.cc:643] P 88f46f5a7adb41b891c333a4424166d2: FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337) complete. Timing: real 0.024s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5011,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:24.521744  6106 maintenance_manager.cc:419] P 88f46f5a7adb41b891c333a4424166d2: Scheduling UndoDeltaBlockGCOp(b5129ee4d3ef41409015d60ff6eb3337): 462 bytes on disk
I20260812 06:20:24.522147  6039 maintenance_manager.cc:643] P 88f46f5a7adb41b891c333a4424166d2: UndoDeltaBlockGCOp(b5129ee4d3ef41409015d60ff6eb3337) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4}
I20260812 06:20:24.522631  6106 maintenance_manager.cc:419] P 88f46f5a7adb41b891c333a4424166d2: Scheduling FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337): perf score=2.188937
I20260812 06:20:24.533975  6039 maintenance_manager.cc:643] P 88f46f5a7adb41b891c333a4424166d2: FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337) complete. Timing: real 0.011s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4221,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:24.534619  6106 maintenance_manager.cc:419] P 88f46f5a7adb41b891c333a4424166d2: Scheduling MajorDeltaCompactionOp(b5129ee4d3ef41409015d60ff6eb3337): perf score=1.000000
I20260812 06:20:24.709002  6039 maintenance_manager.cc:643] P 88f46f5a7adb41b891c333a4424166d2: MajorDeltaCompactionOp(b5129ee4d3ef41409015d60ff6eb3337) complete. Timing: real 0.174s	user 0.148s	sys 0.025s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877337,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1332,"lbm_read_time_us":12190,"lbm_reads_lt_1ms":674,"lbm_write_time_us":34577,"lbm_writes_lt_1ms":643,"mutex_wait_us":367,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":20096,"thread_start_us":77,"threads_started":1,"update_count":3000}
I20260812 06:20:24.709751  6106 maintenance_manager.cc:419] P 88f46f5a7adb41b891c333a4424166d2: Scheduling FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337): perf score=14.095187
I20260812 06:20:24.762964  6039 maintenance_manager.cc:643] P 88f46f5a7adb41b891c333a4424166d2: FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337) complete. Timing: real 0.053s	user 0.022s	sys 0.028s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":25465,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:20:24.763558  6106 maintenance_manager.cc:419] P 88f46f5a7adb41b891c333a4424166d2: Scheduling FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337): perf score=2.188937
I20260812 06:20:24.781718  6039 maintenance_manager.cc:643] P 88f46f5a7adb41b891c333a4424166d2: FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337) complete. Timing: real 0.018s	user 0.011s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6350,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":500}
I20260812 06:20:24.782230  6106 maintenance_manager.cc:419] P 88f46f5a7adb41b891c333a4424166d2: Scheduling MajorDeltaCompactionOp(b5129ee4d3ef41409015d60ff6eb3337): perf score=1.000000
I20260812 06:20:24.933694  6039 maintenance_manager.cc:643] P 88f46f5a7adb41b891c333a4424166d2: MajorDeltaCompactionOp(b5129ee4d3ef41409015d60ff6eb3337) complete. Timing: real 0.151s	user 0.127s	sys 0.019s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":774,"lbm_read_time_us":8606,"lbm_reads_lt_1ms":564,"lbm_write_time_us":29183,"lbm_writes_lt_1ms":543,"mutex_wait_us":107,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:20:24.934438  6106 maintenance_manager.cc:419] P 88f46f5a7adb41b891c333a4424166d2: Scheduling FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337): perf score=14.095187
I20260812 06:20:24.985003  6039 maintenance_manager.cc:643] P 88f46f5a7adb41b891c333a4424166d2: FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337) complete. Timing: real 0.050s	user 0.044s	sys 0.004s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":21748,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:24.985561  6106 maintenance_manager.cc:419] P 88f46f5a7adb41b891c333a4424166d2: Scheduling MajorDeltaCompactionOp(b5129ee4d3ef41409015d60ff6eb3337): perf score=1.000000
I20260812 06:20:25.136735  6039 maintenance_manager.cc:643] P 88f46f5a7adb41b891c333a4424166d2: MajorDeltaCompactionOp(b5129ee4d3ef41409015d60ff6eb3337) complete. Timing: real 0.151s	user 0.091s	sys 0.052s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672156,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":222,"lbm_read_time_us":11558,"lbm_reads_lt_1ms":463,"lbm_write_time_us":23905,"lbm_writes_lt_1ms":443,"mutex_wait_us":24,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":72704,"update_count":2000}
I20260812 06:20:25.137265  6106 maintenance_manager.cc:419] P 88f46f5a7adb41b891c333a4424166d2: Scheduling FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337): perf score=14.095187
I20260812 06:20:25.188102  6039 maintenance_manager.cc:643] P 88f46f5a7adb41b891c333a4424166d2: FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337) complete. Timing: real 0.051s	user 0.020s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20078,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":2000}
I20260812 06:20:25.188633  6106 maintenance_manager.cc:419] P 88f46f5a7adb41b891c333a4424166d2: Scheduling FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337): perf score=2.188937
I20260812 06:20:25.200096  6039 maintenance_manager.cc:643] P 88f46f5a7adb41b891c333a4424166d2: FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4242,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:25.200606  6106 maintenance_manager.cc:419] P 88f46f5a7adb41b891c333a4424166d2: Scheduling MajorDeltaCompactionOp(b5129ee4d3ef41409015d60ff6eb3337): perf score=1.000000
I20260812 06:20:25.397541  6039 maintenance_manager.cc:643] P 88f46f5a7adb41b891c333a4424166d2: MajorDeltaCompactionOp(b5129ee4d3ef41409015d60ff6eb3337) complete. Timing: real 0.197s	user 0.127s	sys 0.054s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":180,"lbm_read_time_us":12649,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30972,"lbm_writes_lt_1ms":543,"mutex_wait_us":43,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8448,"update_count":2500}
I20260812 06:20:25.398211  6106 maintenance_manager.cc:419] P 88f46f5a7adb41b891c333a4424166d2: Scheduling FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337): perf score=14.095187
I20260812 06:20:25.449502  6039 maintenance_manager.cc:643] P 88f46f5a7adb41b891c333a4424166d2: FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337) complete. Timing: real 0.051s	user 0.029s	sys 0.013s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18479,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:25.450778  6106 maintenance_manager.cc:419] P 88f46f5a7adb41b891c333a4424166d2: Scheduling FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337): perf score=2.188937
I20260812 06:20:25.467468  6039 maintenance_manager.cc:643] P 88f46f5a7adb41b891c333a4424166d2: FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337) complete. Timing: real 0.016s	user 0.002s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6447,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:25.468009  6106 maintenance_manager.cc:419] P 88f46f5a7adb41b891c333a4424166d2: Scheduling MajorDeltaCompactionOp(b5129ee4d3ef41409015d60ff6eb3337): perf score=1.000000
I20260812 06:20:25.638741  6039 maintenance_manager.cc:643] P 88f46f5a7adb41b891c333a4424166d2: MajorDeltaCompactionOp(b5129ee4d3ef41409015d60ff6eb3337) complete. Timing: real 0.171s	user 0.105s	sys 0.053s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1041,"lbm_read_time_us":13469,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29979,"lbm_writes_lt_1ms":543,"mutex_wait_us":300,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":73600,"update_count":2500}
I20260812 06:20:25.639426  6106 maintenance_manager.cc:419] P 88f46f5a7adb41b891c333a4424166d2: Scheduling FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337): perf score=14.095187
I20260812 06:20:25.688170  6039 maintenance_manager.cc:643] P 88f46f5a7adb41b891c333a4424166d2: FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337) complete. Timing: real 0.049s	user 0.026s	sys 0.019s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":24268,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:20:25.688673  6106 maintenance_manager.cc:419] P 88f46f5a7adb41b891c333a4424166d2: Scheduling FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337): perf score=2.188937
I20260812 06:20:25.701531  6039 maintenance_manager.cc:643] P 88f46f5a7adb41b891c333a4424166d2: FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337) complete. Timing: real 0.013s	user 0.007s	sys 0.005s 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:20:25.702015  6106 maintenance_manager.cc:419] P 88f46f5a7adb41b891c333a4424166d2: Scheduling MajorDeltaCompactionOp(b5129ee4d3ef41409015d60ff6eb3337): perf score=1.000000
I20260812 06:20:25.853891  6039 maintenance_manager.cc:643] P 88f46f5a7adb41b891c333a4424166d2: MajorDeltaCompactionOp(b5129ee4d3ef41409015d60ff6eb3337) complete. Timing: real 0.152s	user 0.128s	sys 0.012s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":367,"lbm_read_time_us":9056,"lbm_reads_lt_1ms":564,"lbm_write_time_us":30850,"lbm_writes_lt_1ms":543,"mutex_wait_us":85,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:20:25.854707  6106 maintenance_manager.cc:419] P 88f46f5a7adb41b891c333a4424166d2: Scheduling FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337): perf score=14.095187
I20260812 06:20:25.901212  6039 maintenance_manager.cc:643] P 88f46f5a7adb41b891c333a4424166d2: FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337) complete. Timing: real 0.046s	user 0.018s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18770,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:25.901800  6106 maintenance_manager.cc:419] P 88f46f5a7adb41b891c333a4424166d2: Scheduling FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337): perf score=2.188937
I20260812 06:20:25.917802  6039 maintenance_manager.cc:643] P 88f46f5a7adb41b891c333a4424166d2: FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337) complete. Timing: real 0.016s	user 0.008s	sys 0.006s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5969,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:25.918601  6106 maintenance_manager.cc:419] P 88f46f5a7adb41b891c333a4424166d2: Scheduling FlushMRSOp(b5129ee4d3ef41409015d60ff6eb3337): perf score=1.000000
I20260812 06:20:25.952855  6039 maintenance_manager.cc:643] P 88f46f5a7adb41b891c333a4424166d2: FlushMRSOp(b5129ee4d3ef41409015d60ff6eb3337) complete. Timing: real 0.034s	user 0.033s	sys 0.000s Metrics: {"bytes_written":1275445,"cfile_init":1,"dirs.queue_time_us":74,"dirs.run_cpu_time_us":194,"dirs.run_wall_time_us":1436,"drs_written":1,"lbm_read_time_us":71,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1740,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:20:25.953603  6106 maintenance_manager.cc:419] P 88f46f5a7adb41b891c333a4424166d2: Scheduling LogGCOp(b5129ee4d3ef41409015d60ff6eb3337): free 132118513 bytes of WAL
I20260812 06:20:25.953837  6039 log_reader.cc:385] T b5129ee4d3ef41409015d60ff6eb3337: removed 13 log segments from log reader
I20260812 06:20:25.953883  6039 log.cc:1079] T b5129ee4d3ef41409015d60ff6eb3337 P 88f46f5a7adb41b891c333a4424166d2: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/b5129ee4d3ef41409015d60ff6eb3337/wal-000000026 (ops 125-128)
I20260812 06:20:25.953912  6039 log.cc:1079] T b5129ee4d3ef41409015d60ff6eb3337 P 88f46f5a7adb41b891c333a4424166d2: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/b5129ee4d3ef41409015d60ff6eb3337/wal-000000027 (ops 129-133)
I20260812 06:20:25.953975  6039 log.cc:1079] T b5129ee4d3ef41409015d60ff6eb3337 P 88f46f5a7adb41b891c333a4424166d2: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/b5129ee4d3ef41409015d60ff6eb3337/wal-000000028 (ops 134-138)
I20260812 06:20:25.954022  6039 log.cc:1079] T b5129ee4d3ef41409015d60ff6eb3337 P 88f46f5a7adb41b891c333a4424166d2: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/b5129ee4d3ef41409015d60ff6eb3337/wal-000000029 (ops 139-143)
I20260812 06:20:25.954064  6039 log.cc:1079] T b5129ee4d3ef41409015d60ff6eb3337 P 88f46f5a7adb41b891c333a4424166d2: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/b5129ee4d3ef41409015d60ff6eb3337/wal-000000030 (ops 144-148)
I20260812 06:20:25.954123  6039 log.cc:1079] T b5129ee4d3ef41409015d60ff6eb3337 P 88f46f5a7adb41b891c333a4424166d2: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/b5129ee4d3ef41409015d60ff6eb3337/wal-000000031 (ops 149-152)
I20260812 06:20:25.954159  6039 log.cc:1079] T b5129ee4d3ef41409015d60ff6eb3337 P 88f46f5a7adb41b891c333a4424166d2: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/b5129ee4d3ef41409015d60ff6eb3337/wal-000000032 (ops 153-157)
I20260812 06:20:25.954201  6039 log.cc:1079] T b5129ee4d3ef41409015d60ff6eb3337 P 88f46f5a7adb41b891c333a4424166d2: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/b5129ee4d3ef41409015d60ff6eb3337/wal-000000033 (ops 158-162)
I20260812 06:20:25.954237  6039 log.cc:1079] T b5129ee4d3ef41409015d60ff6eb3337 P 88f46f5a7adb41b891c333a4424166d2: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/b5129ee4d3ef41409015d60ff6eb3337/wal-000000034 (ops 163-167)
I20260812 06:20:25.954275  6039 log.cc:1079] T b5129ee4d3ef41409015d60ff6eb3337 P 88f46f5a7adb41b891c333a4424166d2: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/b5129ee4d3ef41409015d60ff6eb3337/wal-000000035 (ops 168-172)
I20260812 06:20:25.954314  6039 log.cc:1079] T b5129ee4d3ef41409015d60ff6eb3337 P 88f46f5a7adb41b891c333a4424166d2: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/b5129ee4d3ef41409015d60ff6eb3337/wal-000000036 (ops 173-177)
I20260812 06:20:25.954357  6039 log.cc:1079] T b5129ee4d3ef41409015d60ff6eb3337 P 88f46f5a7adb41b891c333a4424166d2: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/b5129ee4d3ef41409015d60ff6eb3337/wal-000000037 (ops 178-182)
I20260812 06:20:25.954396  6039 log.cc:1079] T b5129ee4d3ef41409015d60ff6eb3337 P 88f46f5a7adb41b891c333a4424166d2: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/b5129ee4d3ef41409015d60ff6eb3337/wal-000000038 (ops 183-186)
I20260812 06:20:25.980947  6039 maintenance_manager.cc:643] P 88f46f5a7adb41b891c333a4424166d2: LogGCOp(b5129ee4d3ef41409015d60ff6eb3337) complete. Timing: real 0.027s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:20:25.981410  6106 maintenance_manager.cc:419] P 88f46f5a7adb41b891c333a4424166d2: Scheduling FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337): perf score=5.165500
I20260812 06:20:25.997684  6039 maintenance_manager.cc:643] P 88f46f5a7adb41b891c333a4424166d2: FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337) complete. Timing: real 0.016s	user 0.014s	sys 0.000s Metrics: {"bytes_written":6605135,"delete_count":0,"lbm_write_time_us":6582,"lbm_writes_lt_1ms":164,"reinsert_count":0,"update_count":805}
I20260812 06:20:25.998195  6106 maintenance_manager.cc:419] P 88f46f5a7adb41b891c333a4424166d2: Scheduling FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337): perf score=1.000000
I20260812 06:20:26.008747  6039 maintenance_manager.cc:643] P 88f46f5a7adb41b891c333a4424166d2: FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":1600127,"delete_count":0,"lbm_write_time_us":2914,"lbm_writes_lt_1ms":42,"reinsert_count":0,"update_count":195}
I20260812 06:20:26.009260  6106 maintenance_manager.cc:419] P 88f46f5a7adb41b891c333a4424166d2: Scheduling MajorDeltaCompactionOp(b5129ee4d3ef41409015d60ff6eb3337): perf score=1.000000
I20260812 06:20:26.239980  6039 maintenance_manager.cc:643] P 88f46f5a7adb41b891c333a4424166d2: MajorDeltaCompactionOp(b5129ee4d3ef41409015d60ff6eb3337) complete. Timing: real 0.231s	user 0.157s	sys 0.061s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979688,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":790,"lbm_read_time_us":14664,"lbm_reads_lt_1ms":770,"lbm_write_time_us":37289,"lbm_writes_lt_1ms":743,"mutex_wait_us":347,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":15744,"thread_start_us":80,"threads_started":1,"update_count":3500}
I20260812 06:20:26.241122  6106 maintenance_manager.cc:419] P 88f46f5a7adb41b891c333a4424166d2: Scheduling UndoDeltaBlockGCOp(b5129ee4d3ef41409015d60ff6eb3337): 483 bytes on disk
I20260812 06:20:26.241971  6039 maintenance_manager.cc:643] P 88f46f5a7adb41b891c333a4424166d2: UndoDeltaBlockGCOp(b5129ee4d3ef41409015d60ff6eb3337) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":120,"lbm_reads_lt_1ms":4}
I20260812 06:20:26.242885  6106 maintenance_manager.cc:419] P 88f46f5a7adb41b891c333a4424166d2: Scheduling FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337): perf score=18.063937
I20260812 06:20:26.296416  5928 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.870s	user 1.876s	sys 0.128s
I20260812 06:20:26.300319  6039 maintenance_manager.cc:643] P 88f46f5a7adb41b891c333a4424166d2: FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337) complete. Timing: real 0.057s	user 0.032s	sys 0.024s Metrics: {"bytes_written":20512322,"delete_count":0,"lbm_write_time_us":27516,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:20:26.300869  6106 maintenance_manager.cc:419] P 88f46f5a7adb41b891c333a4424166d2: Scheduling FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337): perf score=2.188937
I20260812 06:20:26.310833  6039 maintenance_manager.cc:643] P 88f46f5a7adb41b891c333a4424166d2: FlushDeltaMemStoresOp(b5129ee4d3ef41409015d60ff6eb3337) complete. Timing: real 0.010s	user 0.001s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4114,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:26.311321  6106 maintenance_manager.cc:419] P 88f46f5a7adb41b891c333a4424166d2: Scheduling MajorDeltaCompactionOp(b5129ee4d3ef41409015d60ff6eb3337): perf score=1.000000
I20260812 06:20:26.348492  5928 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.051s	user 0.003s	sys 0.003s
I20260812 06:20:26.349352  5928 tablet_server.cc:179] TabletServer@127.5.202.1:0 shutting down...
I20260812 06:20:26.479137  6039 maintenance_manager.cc:643] P 88f46f5a7adb41b891c333a4424166d2: MajorDeltaCompactionOp(b5129ee4d3ef41409015d60ff6eb3337) complete. Timing: real 0.168s	user 0.107s	sys 0.059s Metrics: {"cfile_cache_hit":30,"cfile_cache_hit_bytes":4262390,"cfile_cache_miss":602,"cfile_cache_miss_bytes":24614719,"cfile_init":4,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":540,"lbm_read_time_us":10608,"lbm_reads_lt_1ms":618,"lbm_write_time_us":27854,"lbm_writes_lt_1ms":643,"mutex_wait_us":23,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":25728,"update_count":3000}
I20260812 06:20:26.479998  5928 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:20:26.480477  5928 tablet_replica.cc:333] T b5129ee4d3ef41409015d60ff6eb3337 P 88f46f5a7adb41b891c333a4424166d2: stopping tablet replica
I20260812 06:20:26.480762  5928 raft_consensus.cc:2243] T b5129ee4d3ef41409015d60ff6eb3337 P 88f46f5a7adb41b891c333a4424166d2 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:26.481040  5928 raft_consensus.cc:2272] T b5129ee4d3ef41409015d60ff6eb3337 P 88f46f5a7adb41b891c333a4424166d2 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:26.497550  5928 tablet_server.cc:196] TabletServer@127.5.202.1:0 shutdown complete.
I20260812 06:20:26.533622  5928 master.cc:562] Master@127.5.202.62:45061 shutting down...
I20260812 06:20:26.537256  5928 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 848f127997374f81a4d85c624ef7b3a6 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:26.537477  5928 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 848f127997374f81a4d85c624ef7b3a6 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:26.537572  5928 tablet_replica.cc:333] T 00000000000000000000000000000000 P 848f127997374f81a4d85c624ef7b3a6: stopping tablet replica
I20260812 06:20:26.550017  5928 master.cc:584] Master@127.5.202.62:45061 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5499 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:20:26.641141  5928 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.5.202.62:39105
I20260812 06:20:26.641655  5928 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:26.643843  6142 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:20:26.643905  6141 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:20:26.644096  5928 server_base.cc:1061] running on GCE node
W20260812 06:20:26.643962  6144 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:20:26.644372  5928 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:26.644418  5928 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:20:26.644434  5928 hybrid_clock.cc:648] HybridClock initialized: now 1786515626644434 us; error 0 us; skew 500 ppm
I20260812 06:20:26.645321  5928 webserver.cc:533] Webserver started at http://127.5.202.62:46387/ using document root <none> and password file <none>
I20260812 06:20:26.645462  5928 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:26.645504  5928 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:26.645581  5928 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:26.645979  5928 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621131617-5928-0/minicluster-data/master-0-root/instance:
uuid: "74420c6141ad40a49284a9a8423ae08f"
format_stamp: "Formatted at 2026-08-12 06:20:26 on dist-test-slave-10pc"
I20260812 06:20:26.647532  5928 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:20:26.648535  6149 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:20:26.648816  5928 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:20:26.648914  5928 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621131617-5928-0/minicluster-data/master-0-root
uuid: "74420c6141ad40a49284a9a8423ae08f"
format_stamp: "Formatted at 2026-08-12 06:20:26 on dist-test-slave-10pc"
I20260812 06:20:26.649004  5928 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621131617-5928-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621131617-5928-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621131617-5928-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:20:26.653214  5928 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:26.653573  5928 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:26.658269  5928 rpc_server.cc:307] RPC server started. Bound to: 127.5.202.62:39105
I20260812 06:20:26.660082  6205 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.5.202.62:39105 every 8 connection(s)
I20260812 06:20:26.671687  6206 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:20:26.677127  6206 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 74420c6141ad40a49284a9a8423ae08f: Bootstrap starting.
I20260812 06:20:26.677965  6206 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 74420c6141ad40a49284a9a8423ae08f: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:26.679121  6206 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 74420c6141ad40a49284a9a8423ae08f: No bootstrap required, opened a new log
I20260812 06:20:26.679492  6206 raft_consensus.cc:359] T 00000000000000000000000000000000 P 74420c6141ad40a49284a9a8423ae08f [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "74420c6141ad40a49284a9a8423ae08f" member_type: VOTER }
I20260812 06:20:26.679577  6206 raft_consensus.cc:385] T 00000000000000000000000000000000 P 74420c6141ad40a49284a9a8423ae08f [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:26.679600  6206 raft_consensus.cc:740] T 00000000000000000000000000000000 P 74420c6141ad40a49284a9a8423ae08f [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 74420c6141ad40a49284a9a8423ae08f, State: Initialized, Role: FOLLOWER
I20260812 06:20:26.679716  6206 consensus_queue.cc:260] T 00000000000000000000000000000000 P 74420c6141ad40a49284a9a8423ae08f [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: "74420c6141ad40a49284a9a8423ae08f" member_type: VOTER }
I20260812 06:20:26.679818  6206 raft_consensus.cc:399] T 00000000000000000000000000000000 P 74420c6141ad40a49284a9a8423ae08f [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:26.679869  6206 raft_consensus.cc:493] T 00000000000000000000000000000000 P 74420c6141ad40a49284a9a8423ae08f [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:26.679934  6206 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 74420c6141ad40a49284a9a8423ae08f [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:26.680780  6206 raft_consensus.cc:515] T 00000000000000000000000000000000 P 74420c6141ad40a49284a9a8423ae08f [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "74420c6141ad40a49284a9a8423ae08f" member_type: VOTER }
I20260812 06:20:26.680954  6206 leader_election.cc:304] T 00000000000000000000000000000000 P 74420c6141ad40a49284a9a8423ae08f [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: 74420c6141ad40a49284a9a8423ae08f; no voters: 
I20260812 06:20:26.681182  6206 leader_election.cc:290] T 00000000000000000000000000000000 P 74420c6141ad40a49284a9a8423ae08f [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:26.681370  6210 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 74420c6141ad40a49284a9a8423ae08f [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:26.681660  6210 raft_consensus.cc:697] T 00000000000000000000000000000000 P 74420c6141ad40a49284a9a8423ae08f [term 1 LEADER]: Becoming Leader. State: Replica: 74420c6141ad40a49284a9a8423ae08f, State: Running, Role: LEADER
I20260812 06:20:26.681710  6206 sys_catalog.cc:565] T 00000000000000000000000000000000 P 74420c6141ad40a49284a9a8423ae08f [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:20:26.681828  6210 consensus_queue.cc:237] T 00000000000000000000000000000000 P 74420c6141ad40a49284a9a8423ae08f [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: "74420c6141ad40a49284a9a8423ae08f" member_type: VOTER }
I20260812 06:20:26.682355  6211 sys_catalog.cc:455] T 00000000000000000000000000000000 P 74420c6141ad40a49284a9a8423ae08f [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "74420c6141ad40a49284a9a8423ae08f" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "74420c6141ad40a49284a9a8423ae08f" member_type: VOTER } }
I20260812 06:20:26.682415  6212 sys_catalog.cc:455] T 00000000000000000000000000000000 P 74420c6141ad40a49284a9a8423ae08f [sys.catalog]: SysCatalogTable state changed. Reason: New leader 74420c6141ad40a49284a9a8423ae08f. Latest consensus state: current_term: 1 leader_uuid: "74420c6141ad40a49284a9a8423ae08f" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "74420c6141ad40a49284a9a8423ae08f" member_type: VOTER } }
I20260812 06:20:26.682555  6212 sys_catalog.cc:458] T 00000000000000000000000000000000 P 74420c6141ad40a49284a9a8423ae08f [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:26.682536  6211 sys_catalog.cc:458] T 00000000000000000000000000000000 P 74420c6141ad40a49284a9a8423ae08f [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:26.682914  6220 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:20:26.683890  6220 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:20:26.684072  5928 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:20:26.685868  6220 catalog_manager.cc:1383] Generated new cluster ID: e9bf9d8a887d4ec39e60877f4fd5bdca
I20260812 06:20:26.685952  6220 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:20:26.695926  6220 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:20:26.696580  6220 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:20:26.704058  6220 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 74420c6141ad40a49284a9a8423ae08f: Generated new TSK 0
I20260812 06:20:26.704298  6220 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:20:26.716614  5928 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:26.718921  6231 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:20:26.718845  6235 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:20:26.718999  5928 server_base.cc:1061] running on GCE node
W20260812 06:20:26.718860  6232 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:20:26.719340  5928 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:26.719386  5928 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:20:26.719403  5928 hybrid_clock.cc:648] HybridClock initialized: now 1786515626719402 us; error 0 us; skew 500 ppm
I20260812 06:20:26.720292  5928 webserver.cc:533] Webserver started at http://127.5.202.1:40749/ using document root <none> and password file <none>
I20260812 06:20:26.720530  5928 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:26.720608  5928 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:26.720713  5928 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:26.721141  5928 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621131617-5928-0/minicluster-data/ts-0-root/instance:
uuid: "d3658f55a8284d068408ccb41c0e67f5"
format_stamp: "Formatted at 2026-08-12 06:20:26 on dist-test-slave-10pc"
I20260812 06:20:26.722754  5928 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:20:26.723794  6240 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:20:26.724085  5928 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:20:26.724200  5928 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621131617-5928-0/minicluster-data/ts-0-root
uuid: "d3658f55a8284d068408ccb41c0e67f5"
format_stamp: "Formatted at 2026-08-12 06:20:26 on dist-test-slave-10pc"
I20260812 06:20:26.724284  5928 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621131617-5928-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621131617-5928-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621131617-5928-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:20:26.743872  5928 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:26.744318  5928 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:26.744711  5928 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:20:26.745254  5928 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:20:26.745322  5928 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:26.745388  5928 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:20:26.745438  5928 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:26.749859  5928 rpc_server.cc:307] RPC server started. Bound to: 127.5.202.1:36611
I20260812 06:20:26.749893  6315 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.5.202.1:36611 every 8 connection(s)
I20260812 06:20:26.760735  6316 heartbeater.cc:344] Connected to a master server at 127.5.202.62:39105
I20260812 06:20:26.760892  6316 heartbeater.cc:461] Registering TS with master...
I20260812 06:20:26.761204  6316 heartbeater.cc:507] Master 127.5.202.62:39105 requested a full tablet report, sending...
I20260812 06:20:26.761932  6168 ts_manager.cc:194] Registered new tserver with Master: d3658f55a8284d068408ccb41c0e67f5 (127.5.202.1:36611)
I20260812 06:20:26.762643  6168 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:38132
I20260812 06:20:26.762751  5928 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012388156s
I20260812 06:20:26.770604  6168 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:38148:
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:20:26.779371  6273 tablet_service.cc:1511] Processing CreateTablet for tablet 6d8d03af567b4d018f4d981cc156ec95 (DEFAULT_TABLE table=heavy-update-compaction-test [id=09daff907e034cddbb9e9c4d39306304]), partition=
I20260812 06:20:26.779623  6273 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 6d8d03af567b4d018f4d981cc156ec95. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:20:26.781584  6329 tablet_bootstrap.cc:492] T 6d8d03af567b4d018f4d981cc156ec95 P d3658f55a8284d068408ccb41c0e67f5: Bootstrap starting.
I20260812 06:20:26.782469  6329 tablet_bootstrap.cc:654] T 6d8d03af567b4d018f4d981cc156ec95 P d3658f55a8284d068408ccb41c0e67f5: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:26.783766  6329 tablet_bootstrap.cc:492] T 6d8d03af567b4d018f4d981cc156ec95 P d3658f55a8284d068408ccb41c0e67f5: No bootstrap required, opened a new log
I20260812 06:20:26.783874  6329 ts_tablet_manager.cc:1403] T 6d8d03af567b4d018f4d981cc156ec95 P d3658f55a8284d068408ccb41c0e67f5: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:20:26.784318  6329 raft_consensus.cc:359] T 6d8d03af567b4d018f4d981cc156ec95 P d3658f55a8284d068408ccb41c0e67f5 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d3658f55a8284d068408ccb41c0e67f5" member_type: VOTER last_known_addr { host: "127.5.202.1" port: 36611 } }
I20260812 06:20:26.784430  6329 raft_consensus.cc:385] T 6d8d03af567b4d018f4d981cc156ec95 P d3658f55a8284d068408ccb41c0e67f5 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:26.784502  6329 raft_consensus.cc:740] T 6d8d03af567b4d018f4d981cc156ec95 P d3658f55a8284d068408ccb41c0e67f5 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: d3658f55a8284d068408ccb41c0e67f5, State: Initialized, Role: FOLLOWER
I20260812 06:20:26.784648  6329 consensus_queue.cc:260] T 6d8d03af567b4d018f4d981cc156ec95 P d3658f55a8284d068408ccb41c0e67f5 [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: "d3658f55a8284d068408ccb41c0e67f5" member_type: VOTER last_known_addr { host: "127.5.202.1" port: 36611 } }
I20260812 06:20:26.784755  6329 raft_consensus.cc:399] T 6d8d03af567b4d018f4d981cc156ec95 P d3658f55a8284d068408ccb41c0e67f5 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:26.784797  6329 raft_consensus.cc:493] T 6d8d03af567b4d018f4d981cc156ec95 P d3658f55a8284d068408ccb41c0e67f5 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:26.784844  6329 raft_consensus.cc:3060] T 6d8d03af567b4d018f4d981cc156ec95 P d3658f55a8284d068408ccb41c0e67f5 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:26.785791  6329 raft_consensus.cc:515] T 6d8d03af567b4d018f4d981cc156ec95 P d3658f55a8284d068408ccb41c0e67f5 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d3658f55a8284d068408ccb41c0e67f5" member_type: VOTER last_known_addr { host: "127.5.202.1" port: 36611 } }
I20260812 06:20:26.785946  6329 leader_election.cc:304] T 6d8d03af567b4d018f4d981cc156ec95 P d3658f55a8284d068408ccb41c0e67f5 [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: d3658f55a8284d068408ccb41c0e67f5; no voters: 
I20260812 06:20:26.786170  6329 leader_election.cc:290] T 6d8d03af567b4d018f4d981cc156ec95 P d3658f55a8284d068408ccb41c0e67f5 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:26.786365  6331 raft_consensus.cc:2804] T 6d8d03af567b4d018f4d981cc156ec95 P d3658f55a8284d068408ccb41c0e67f5 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:26.786582  6329 ts_tablet_manager.cc:1434] T 6d8d03af567b4d018f4d981cc156ec95 P d3658f55a8284d068408ccb41c0e67f5: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:20:26.786609  6316 heartbeater.cc:499] Master 127.5.202.62:39105 was elected leader, sending a full tablet report...
I20260812 06:20:26.786602  6331 raft_consensus.cc:697] T 6d8d03af567b4d018f4d981cc156ec95 P d3658f55a8284d068408ccb41c0e67f5 [term 1 LEADER]: Becoming Leader. State: Replica: d3658f55a8284d068408ccb41c0e67f5, State: Running, Role: LEADER
I20260812 06:20:26.786841  6331 consensus_queue.cc:237] T 6d8d03af567b4d018f4d981cc156ec95 P d3658f55a8284d068408ccb41c0e67f5 [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: "d3658f55a8284d068408ccb41c0e67f5" member_type: VOTER last_known_addr { host: "127.5.202.1" port: 36611 } }
I20260812 06:20:26.788128  6168 catalog_manager.cc:5719] T 6d8d03af567b4d018f4d981cc156ec95 P d3658f55a8284d068408ccb41c0e67f5 reported cstate change: term changed from 0 to 1, leader changed from <none> to d3658f55a8284d068408ccb41c0e67f5 (127.5.202.1). New cstate: current_term: 1 leader_uuid: "d3658f55a8284d068408ccb41c0e67f5" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d3658f55a8284d068408ccb41c0e67f5" member_type: VOTER last_known_addr { host: "127.5.202.1" port: 36611 } health_report { overall_health: HEALTHY } } }
I20260812 06:20:26.849105  5928 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.053s	user 0.015s	sys 0.008s
I20260812 06:20:27.001019  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling FlushMRSOp(6d8d03af567b4d018f4d981cc156ec95): perf score=19.054940
I20260812 06:20:27.149029  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: FlushMRSOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.148s	user 0.103s	sys 0.044s Metrics: {"bytes_written":12307491,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":80,"dirs.run_cpu_time_us":216,"dirs.run_wall_time_us":854,"drs_written":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4,"lbm_write_time_us":38008,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:20:27.149804  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling LogGCOp(6d8d03af567b4d018f4d981cc156ec95): free 20743831 bytes of WAL
I20260812 06:20:27.150069  6246 log_reader.cc:385] T 6d8d03af567b4d018f4d981cc156ec95: removed 2 log segments from log reader
I20260812 06:20:27.150139  6246 log.cc:1079] T 6d8d03af567b4d018f4d981cc156ec95 P d3658f55a8284d068408ccb41c0e67f5: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/6d8d03af567b4d018f4d981cc156ec95/wal-000000001 (ops 1-6)
I20260812 06:20:27.150184  6246 log.cc:1079] T 6d8d03af567b4d018f4d981cc156ec95 P d3658f55a8284d068408ccb41c0e67f5: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/6d8d03af567b4d018f4d981cc156ec95/wal-000000002 (ops 7-11)
I20260812 06:20:27.156668  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: LogGCOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.007s	user 0.000s	sys 0.006s Metrics: {}
I20260812 06:20:27.157200  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling UndoDeltaBlockGCOp(6d8d03af567b4d018f4d981cc156ec95): 16411392 bytes on disk
I20260812 06:20:27.157822  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: UndoDeltaBlockGCOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":105,"lbm_reads_lt_1ms":4}
I20260812 06:20:27.158465  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95): perf score=2.188937
I20260812 06:20:27.185034  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.026s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5810,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:27.185577  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95): perf score=2.188937
I20260812 06:20:27.211012  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.025s	user 0.008s	sys 0.015s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5903,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:27.211738  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling MajorDeltaCompactionOp(6d8d03af567b4d018f4d981cc156ec95): perf score=1.000000
I20260812 06:20:27.415711  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: MajorDeltaCompactionOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.204s	user 0.117s	sys 0.077s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774808,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":536,"lbm_read_time_us":14913,"lbm_reads_lt_1ms":569,"lbm_write_time_us":30367,"lbm_writes_lt_1ms":543,"mutex_wait_us":40,"peak_mem_usage":63115900,"reinsert_count":0,"thread_start_us":335,"threads_started":5,"update_count":2500}
I20260812 06:20:27.416290  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95): perf score=14.095187
I20260812 06:20:27.473526  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.057s	user 0.036s	sys 0.011s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":21710,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:27.474049  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95): perf score=2.188937
I20260812 06:20:27.485953  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.012s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4148,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:27.486431  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling MajorDeltaCompactionOp(6d8d03af567b4d018f4d981cc156ec95): perf score=1.000000
I20260812 06:20:27.675132  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: MajorDeltaCompactionOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.189s	user 0.135s	sys 0.037s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":364,"lbm_read_time_us":12063,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29376,"lbm_writes_lt_1ms":543,"mutex_wait_us":71,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":24320,"update_count":2500}
I20260812 06:20:27.675724  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95): perf score=14.095187
I20260812 06:20:27.727193  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.051s	user 0.023s	sys 0.019s Metrics: {"bytes_written":16409897,"delete_count":0,"lbm_write_time_us":20310,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:27.727679  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95): perf score=2.188937
I20260812 06:20:27.738596  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.011s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4149,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:27.739369  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling MajorDeltaCompactionOp(6d8d03af567b4d018f4d981cc156ec95): perf score=1.000000
I20260812 06:20:27.887038  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: MajorDeltaCompactionOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.147s	user 0.111s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":931,"lbm_read_time_us":10911,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28160,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2500}
I20260812 06:20:27.887833  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95): perf score=10.126437
I20260812 06:20:27.921206  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.033s	user 0.025s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14305,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:27.921875  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95): perf score=2.188937
I20260812 06:20:27.944027  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.019s	user 0.011s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6688,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:27.944572  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling MajorDeltaCompactionOp(6d8d03af567b4d018f4d981cc156ec95): perf score=1.000000
I20260812 06:20:28.072949  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: MajorDeltaCompactionOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.128s	user 0.094s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":226,"lbm_read_time_us":7655,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23808,"lbm_writes_lt_1ms":443,"mutex_wait_us":44,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":29312,"update_count":2000}
I20260812 06:20:28.077044  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95): perf score=11.118625
I20260812 06:20:28.119084  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.040s	user 0.017s	sys 0.019s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":18692,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:20:28.120153  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95): perf score=2.188937
I20260812 06:20:28.136420  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.016s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5071,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:28.136950  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling MajorDeltaCompactionOp(6d8d03af567b4d018f4d981cc156ec95): perf score=1.000000
I20260812 06:20:28.277282  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: MajorDeltaCompactionOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.140s	user 0.095s	sys 0.038s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":205,"lbm_read_time_us":7406,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27520,"lbm_writes_lt_1ms":443,"mutex_wait_us":47,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7936,"update_count":2000}
I20260812 06:20:28.277979  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95): perf score=11.118625
I20260812 06:20:28.326634  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.048s	user 0.027s	sys 0.019s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15644,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:28.327308  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95): perf score=2.188937
I20260812 06:20:28.344337  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.017s	user 0.015s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6405,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:28.345170  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling MajorDeltaCompactionOp(6d8d03af567b4d018f4d981cc156ec95): perf score=1.000000
I20260812 06:20:28.503232  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: MajorDeltaCompactionOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.158s	user 0.131s	sys 0.026s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":365,"lbm_read_time_us":11096,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25250,"lbm_writes_lt_1ms":443,"mutex_wait_us":68,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5120,"update_count":2000}
I20260812 06:20:28.504024  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95): perf score=10.126437
I20260812 06:20:28.543715  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.039s	user 0.035s	sys 0.001s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16934,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:20:28.544304  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95): perf score=2.188937
I20260812 06:20:28.560624  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.016s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6344,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:28.561257  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling FlushMRSOp(6d8d03af567b4d018f4d981cc156ec95): perf score=1.000000
I20260812 06:20:28.593320  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: FlushMRSOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.032s	user 0.030s	sys 0.001s Metrics: {"bytes_written":1275443,"cfile_init":1,"dirs.queue_time_us":88,"dirs.run_cpu_time_us":234,"dirs.run_wall_time_us":1420,"drs_written":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2093,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:20:28.594403  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling LogGCOp(6d8d03af567b4d018f4d981cc156ec95): free 121006479 bytes of WAL
I20260812 06:20:28.594681  6246 log_reader.cc:385] T 6d8d03af567b4d018f4d981cc156ec95: removed 12 log segments from log reader
I20260812 06:20:28.594743  6246 log.cc:1079] T 6d8d03af567b4d018f4d981cc156ec95 P d3658f55a8284d068408ccb41c0e67f5: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/6d8d03af567b4d018f4d981cc156ec95/wal-000000003 (ops 12-16)
I20260812 06:20:28.594785  6246 log.cc:1079] T 6d8d03af567b4d018f4d981cc156ec95 P d3658f55a8284d068408ccb41c0e67f5: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/6d8d03af567b4d018f4d981cc156ec95/wal-000000004 (ops 17-21)
I20260812 06:20:28.594820  6246 log.cc:1079] T 6d8d03af567b4d018f4d981cc156ec95 P d3658f55a8284d068408ccb41c0e67f5: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/6d8d03af567b4d018f4d981cc156ec95/wal-000000005 (ops 22-26)
I20260812 06:20:28.594858  6246 log.cc:1079] T 6d8d03af567b4d018f4d981cc156ec95 P d3658f55a8284d068408ccb41c0e67f5: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/6d8d03af567b4d018f4d981cc156ec95/wal-000000006 (ops 27-31)
I20260812 06:20:28.594900  6246 log.cc:1079] T 6d8d03af567b4d018f4d981cc156ec95 P d3658f55a8284d068408ccb41c0e67f5: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/6d8d03af567b4d018f4d981cc156ec95/wal-000000007 (ops 32-36)
I20260812 06:20:28.594939  6246 log.cc:1079] T 6d8d03af567b4d018f4d981cc156ec95 P d3658f55a8284d068408ccb41c0e67f5: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/6d8d03af567b4d018f4d981cc156ec95/wal-000000008 (ops 37-41)
I20260812 06:20:28.594975  6246 log.cc:1079] T 6d8d03af567b4d018f4d981cc156ec95 P d3658f55a8284d068408ccb41c0e67f5: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/6d8d03af567b4d018f4d981cc156ec95/wal-000000009 (ops 42-46)
I20260812 06:20:28.595017  6246 log.cc:1079] T 6d8d03af567b4d018f4d981cc156ec95 P d3658f55a8284d068408ccb41c0e67f5: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/6d8d03af567b4d018f4d981cc156ec95/wal-000000010 (ops 47-50)
I20260812 06:20:28.595049  6246 log.cc:1079] T 6d8d03af567b4d018f4d981cc156ec95 P d3658f55a8284d068408ccb41c0e67f5: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/6d8d03af567b4d018f4d981cc156ec95/wal-000000011 (ops 51-55)
I20260812 06:20:28.595084  6246 log.cc:1079] T 6d8d03af567b4d018f4d981cc156ec95 P d3658f55a8284d068408ccb41c0e67f5: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/6d8d03af567b4d018f4d981cc156ec95/wal-000000012 (ops 56-60)
I20260812 06:20:28.595117  6246 log.cc:1079] T 6d8d03af567b4d018f4d981cc156ec95 P d3658f55a8284d068408ccb41c0e67f5: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/6d8d03af567b4d018f4d981cc156ec95/wal-000000013 (ops 61-65)
I20260812 06:20:28.595147  6246 log.cc:1079] T 6d8d03af567b4d018f4d981cc156ec95 P d3658f55a8284d068408ccb41c0e67f5: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/6d8d03af567b4d018f4d981cc156ec95/wal-000000014 (ops 66-70)
I20260812 06:20:28.622788  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: LogGCOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.028s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:20:28.623215  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95): perf score=3.181125
I20260812 06:20:28.649749  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.026s	user 0.001s	sys 0.024s Metrics: {"bytes_written":5169287,"delete_count":0,"lbm_write_time_us":5971,"lbm_writes_lt_1ms":129,"reinsert_count":0,"update_count":630}
I20260812 06:20:28.650255  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling UndoDeltaBlockGCOp(6d8d03af567b4d018f4d981cc156ec95): 482 bytes on disk
I20260812 06:20:28.650738  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: UndoDeltaBlockGCOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4}
I20260812 06:20:28.651233  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95): perf score=1.196750
I20260812 06:20:28.659770  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.008s	user 0.000s	sys 0.007s Metrics: {"bytes_written":3036005,"delete_count":0,"lbm_write_time_us":3304,"lbm_writes_lt_1ms":77,"reinsert_count":0,"update_count":370}
I20260812 06:20:28.660141  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling MajorDeltaCompactionOp(6d8d03af567b4d018f4d981cc156ec95): perf score=1.000000
I20260812 06:20:28.858763  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: MajorDeltaCompactionOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.198s	user 0.136s	sys 0.063s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877314,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":717,"lbm_read_time_us":13464,"lbm_reads_lt_1ms":674,"lbm_write_time_us":33226,"lbm_writes_lt_1ms":643,"mutex_wait_us":67,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":77,"threads_started":1,"update_count":3000}
I20260812 06:20:28.859627  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95): perf score=14.095187
I20260812 06:20:28.924778  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.065s	user 0.025s	sys 0.039s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":24793,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:20:28.925369  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95): perf score=2.188937
I20260812 06:20:28.941712  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.016s	user 0.005s	sys 0.010s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6073,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:28.942283  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling MajorDeltaCompactionOp(6d8d03af567b4d018f4d981cc156ec95): perf score=1.000000
I20260812 06:20:29.125420  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: MajorDeltaCompactionOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.183s	user 0.130s	sys 0.053s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":546,"lbm_read_time_us":11000,"lbm_reads_lt_1ms":568,"lbm_write_time_us":31113,"lbm_writes_lt_1ms":543,"mutex_wait_us":71,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4352,"update_count":2500}
I20260812 06:20:29.126127  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95): perf score=14.095187
I20260812 06:20:29.173713  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.047s	user 0.034s	sys 0.011s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20417,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:29.174230  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95): perf score=2.188937
I20260812 06:20:29.190028  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.016s	user 0.001s	sys 0.013s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6526,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:29.190522  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling MajorDeltaCompactionOp(6d8d03af567b4d018f4d981cc156ec95): perf score=1.000000
I20260812 06:20:29.401484  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: MajorDeltaCompactionOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.211s	user 0.137s	sys 0.061s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":213,"lbm_read_time_us":11379,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32487,"lbm_writes_lt_1ms":543,"mutex_wait_us":70,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12160,"update_count":2500}
I20260812 06:20:29.402302  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95): perf score=14.095187
I20260812 06:20:29.455495  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.053s	user 0.025s	sys 0.021s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21927,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:29.456014  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95): perf score=2.188937
I20260812 06:20:29.467700  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4278,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:29.468192  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling MajorDeltaCompactionOp(6d8d03af567b4d018f4d981cc156ec95): perf score=1.000000
I20260812 06:20:29.616721  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: MajorDeltaCompactionOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.148s	user 0.122s	sys 0.025s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":970,"lbm_read_time_us":10923,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28358,"lbm_writes_lt_1ms":543,"mutex_wait_us":323,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8064,"update_count":2500}
I20260812 06:20:29.617476  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95): perf score=11.118625
I20260812 06:20:29.658763  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.041s	user 0.025s	sys 0.014s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":18130,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:29.659252  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95): perf score=2.188937
I20260812 06:20:29.670802  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4225,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:29.671283  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling MajorDeltaCompactionOp(6d8d03af567b4d018f4d981cc156ec95): perf score=1.000000
I20260812 06:20:29.795301  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: MajorDeltaCompactionOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.124s	user 0.096s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672269,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":304,"lbm_read_time_us":8842,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22933,"lbm_writes_lt_1ms":443,"mutex_wait_us":134,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7808,"update_count":2000}
I20260812 06:20:29.795794  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95): perf score=10.126437
I20260812 06:20:29.854435  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.058s	user 0.033s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18648,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:29.855044  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95): perf score=2.188937
I20260812 06:20:29.874825  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.020s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5869,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:29.875392  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling MajorDeltaCompactionOp(6d8d03af567b4d018f4d981cc156ec95): perf score=1.000000
I20260812 06:20:30.001178  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: MajorDeltaCompactionOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.126s	user 0.093s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":941,"lbm_read_time_us":9837,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23262,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7680,"update_count":2000}
I20260812 06:20:30.001741  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95): perf score=10.126437
I20260812 06:20:30.062734  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.061s	user 0.039s	sys 0.015s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":20407,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:30.063297  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95): perf score=2.188937
I20260812 06:20:30.074373  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4311,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:30.074930  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling FlushMRSOp(6d8d03af567b4d018f4d981cc156ec95): perf score=1.000000
I20260812 06:20:30.117918  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: FlushMRSOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.043s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":68,"dirs.run_cpu_time_us":234,"dirs.run_wall_time_us":1382,"drs_written":1,"lbm_read_time_us":69,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1595,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:20:30.118548  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling LogGCOp(6d8d03af567b4d018f4d981cc156ec95): free 124257201 bytes of WAL
I20260812 06:20:30.118778  6246 log_reader.cc:385] T 6d8d03af567b4d018f4d981cc156ec95: removed 12 log segments from log reader
I20260812 06:20:30.118824  6246 log.cc:1079] T 6d8d03af567b4d018f4d981cc156ec95 P d3658f55a8284d068408ccb41c0e67f5: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/6d8d03af567b4d018f4d981cc156ec95/wal-000000015 (ops 71-75)
I20260812 06:20:30.118853  6246 log.cc:1079] T 6d8d03af567b4d018f4d981cc156ec95 P d3658f55a8284d068408ccb41c0e67f5: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/6d8d03af567b4d018f4d981cc156ec95/wal-000000016 (ops 76-80)
I20260812 06:20:30.118922  6246 log.cc:1079] T 6d8d03af567b4d018f4d981cc156ec95 P d3658f55a8284d068408ccb41c0e67f5: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/6d8d03af567b4d018f4d981cc156ec95/wal-000000017 (ops 81-85)
I20260812 06:20:30.118953  6246 log.cc:1079] T 6d8d03af567b4d018f4d981cc156ec95 P d3658f55a8284d068408ccb41c0e67f5: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/6d8d03af567b4d018f4d981cc156ec95/wal-000000018 (ops 86-90)
I20260812 06:20:30.118990  6246 log.cc:1079] T 6d8d03af567b4d018f4d981cc156ec95 P d3658f55a8284d068408ccb41c0e67f5: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/6d8d03af567b4d018f4d981cc156ec95/wal-000000019 (ops 91-95)
I20260812 06:20:30.119029  6246 log.cc:1079] T 6d8d03af567b4d018f4d981cc156ec95 P d3658f55a8284d068408ccb41c0e67f5: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/6d8d03af567b4d018f4d981cc156ec95/wal-000000020 (ops 96-100)
I20260812 06:20:30.119069  6246 log.cc:1079] T 6d8d03af567b4d018f4d981cc156ec95 P d3658f55a8284d068408ccb41c0e67f5: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/6d8d03af567b4d018f4d981cc156ec95/wal-000000021 (ops 101-105)
I20260812 06:20:30.119109  6246 log.cc:1079] T 6d8d03af567b4d018f4d981cc156ec95 P d3658f55a8284d068408ccb41c0e67f5: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/6d8d03af567b4d018f4d981cc156ec95/wal-000000022 (ops 106-110)
I20260812 06:20:30.119153  6246 log.cc:1079] T 6d8d03af567b4d018f4d981cc156ec95 P d3658f55a8284d068408ccb41c0e67f5: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/6d8d03af567b4d018f4d981cc156ec95/wal-000000023 (ops 111-115)
I20260812 06:20:30.119194  6246 log.cc:1079] T 6d8d03af567b4d018f4d981cc156ec95 P d3658f55a8284d068408ccb41c0e67f5: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/6d8d03af567b4d018f4d981cc156ec95/wal-000000024 (ops 116-120)
I20260812 06:20:30.119220  6246 log.cc:1079] T 6d8d03af567b4d018f4d981cc156ec95 P d3658f55a8284d068408ccb41c0e67f5: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/6d8d03af567b4d018f4d981cc156ec95/wal-000000025 (ops 121-124)
I20260812 06:20:30.119256  6246 log.cc:1079] T 6d8d03af567b4d018f4d981cc156ec95 P d3658f55a8284d068408ccb41c0e67f5: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/6d8d03af567b4d018f4d981cc156ec95/wal-000000026 (ops 125-129)
I20260812 06:20:30.144524  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: LogGCOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.026s	user 0.003s	sys 0.022s Metrics: {}
I20260812 06:20:30.145042  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95): perf score=2.188937
I20260812 06:20:30.163362  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.018s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4353,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:30.163862  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling UndoDeltaBlockGCOp(6d8d03af567b4d018f4d981cc156ec95): 463 bytes on disk
I20260812 06:20:30.164369  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: UndoDeltaBlockGCOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":101,"lbm_reads_lt_1ms":4}
I20260812 06:20:30.164919  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95): perf score=2.188937
I20260812 06:20:30.181483  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.016s	user 0.012s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6186,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:30.182091  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling MajorDeltaCompactionOp(6d8d03af567b4d018f4d981cc156ec95): perf score=1.000000
I20260812 06:20:30.388358  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: MajorDeltaCompactionOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.206s	user 0.133s	sys 0.072s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877338,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":783,"lbm_read_time_us":13514,"lbm_reads_lt_1ms":674,"lbm_write_time_us":35110,"lbm_writes_lt_1ms":643,"mutex_wait_us":32,"peak_mem_usage":75542472,"reinsert_count":0,"thread_start_us":101,"threads_started":1,"update_count":3000}
I20260812 06:20:30.389761  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95): perf score=14.095187
I20260812 06:20:30.448565  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.059s	user 0.030s	sys 0.023s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23054,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:30.449183  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95): perf score=2.188937
I20260812 06:20:30.466355  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.017s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6516,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:30.467008  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling MajorDeltaCompactionOp(6d8d03af567b4d018f4d981cc156ec95): perf score=1.000000
I20260812 06:20:30.643585  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: MajorDeltaCompactionOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.176s	user 0.129s	sys 0.045s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":981,"lbm_read_time_us":13010,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28879,"lbm_writes_lt_1ms":543,"mutex_wait_us":275,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9472,"update_count":2500}
I20260812 06:20:30.644116  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95): perf score=14.095187
I20260812 06:20:30.707145  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.063s	user 0.021s	sys 0.030s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":20179,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:30.707672  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95): perf score=2.188937
I20260812 06:20:30.718456  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4298,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:30.718993  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling MajorDeltaCompactionOp(6d8d03af567b4d018f4d981cc156ec95): perf score=1.000000
I20260812 06:20:30.890861  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: MajorDeltaCompactionOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.172s	user 0.116s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":181,"lbm_read_time_us":13403,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27807,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3456,"update_count":2500}
I20260812 06:20:30.891371  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95): perf score=14.095187
I20260812 06:20:30.962093  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.071s	user 0.028s	sys 0.037s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":25314,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:30.962719  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95): perf score=2.188937
I20260812 06:20:30.974675  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.012s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4748,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:30.975167  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling MajorDeltaCompactionOp(6d8d03af567b4d018f4d981cc156ec95): perf score=1.000000
I20260812 06:20:31.159396  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: MajorDeltaCompactionOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.184s	user 0.119s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":936,"lbm_read_time_us":12701,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30191,"lbm_writes_lt_1ms":543,"mutex_wait_us":240,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3456,"update_count":2500}
I20260812 06:20:31.160220  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95): perf score=11.118625
I20260812 06:20:31.197126  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.037s	user 0.025s	sys 0.011s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":15302,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:31.197649  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95): perf score=2.188937
I20260812 06:20:31.226487  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.029s	user 0.014s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4773,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:31.227077  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95): perf score=2.188937
I20260812 06:20:31.237898  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4176,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:31.238644  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling MajorDeltaCompactionOp(6d8d03af567b4d018f4d981cc156ec95): perf score=1.000000
I20260812 06:20:31.443449  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: MajorDeltaCompactionOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.205s	user 0.162s	sys 0.039s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":629,"lbm_read_time_us":15718,"lbm_reads_lt_1ms":573,"lbm_write_time_us":32643,"lbm_writes_lt_1ms":543,"mutex_wait_us":341,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5248,"update_count":2500}
I20260812 06:20:31.444077  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95): perf score=11.118625
I20260812 06:20:31.478173  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.034s	user 0.029s	sys 0.003s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14288,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:31.478873  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95): perf score=2.188937
I20260812 06:20:31.502923  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.024s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5496,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:31.503496  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95): perf score=2.188937
I20260812 06:20:31.513775  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3906,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:31.514262  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling MajorDeltaCompactionOp(6d8d03af567b4d018f4d981cc156ec95): perf score=1.000000
I20260812 06:20:31.685847  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: MajorDeltaCompactionOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.171s	user 0.113s	sys 0.056s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774798,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":243,"lbm_read_time_us":9344,"lbm_reads_lt_1ms":573,"lbm_write_time_us":27751,"lbm_writes_lt_1ms":543,"mutex_wait_us":32,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9600,"update_count":2500}
I20260812 06:20:31.686619  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95): perf score=14.095187
I20260812 06:20:31.735970  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.049s	user 0.025s	sys 0.020s Metrics: {"bytes_written":16409899,"delete_count":0,"lbm_write_time_us":21838,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:20:31.736595  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95): perf score=2.188937
I20260812 06:20:31.748718  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4099,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:31.749281  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling FlushMRSOp(6d8d03af567b4d018f4d981cc156ec95): perf score=1.000000
I20260812 06:20:31.781658  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: FlushMRSOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.032s	user 0.026s	sys 0.005s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":78,"dirs.run_cpu_time_us":230,"dirs.run_wall_time_us":1251,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1820,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:20:31.782445  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling LogGCOp(6d8d03af567b4d018f4d981cc156ec95): free 133024646 bytes of WAL
I20260812 06:20:31.782671  6246 log_reader.cc:385] T 6d8d03af567b4d018f4d981cc156ec95: removed 13 log segments from log reader
I20260812 06:20:31.782725  6246 log.cc:1079] T 6d8d03af567b4d018f4d981cc156ec95 P d3658f55a8284d068408ccb41c0e67f5: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/6d8d03af567b4d018f4d981cc156ec95/wal-000000027 (ops 130-134)
I20260812 06:20:31.782755  6246 log.cc:1079] T 6d8d03af567b4d018f4d981cc156ec95 P d3658f55a8284d068408ccb41c0e67f5: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/6d8d03af567b4d018f4d981cc156ec95/wal-000000028 (ops 135-139)
I20260812 06:20:31.782819  6246 log.cc:1079] T 6d8d03af567b4d018f4d981cc156ec95 P d3658f55a8284d068408ccb41c0e67f5: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/6d8d03af567b4d018f4d981cc156ec95/wal-000000029 (ops 140-144)
I20260812 06:20:31.782881  6246 log.cc:1079] T 6d8d03af567b4d018f4d981cc156ec95 P d3658f55a8284d068408ccb41c0e67f5: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/6d8d03af567b4d018f4d981cc156ec95/wal-000000030 (ops 145-148)
I20260812 06:20:31.782920  6246 log.cc:1079] T 6d8d03af567b4d018f4d981cc156ec95 P d3658f55a8284d068408ccb41c0e67f5: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/6d8d03af567b4d018f4d981cc156ec95/wal-000000031 (ops 149-153)
I20260812 06:20:31.782963  6246 log.cc:1079] T 6d8d03af567b4d018f4d981cc156ec95 P d3658f55a8284d068408ccb41c0e67f5: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/6d8d03af567b4d018f4d981cc156ec95/wal-000000032 (ops 154-158)
I20260812 06:20:31.783000  6246 log.cc:1079] T 6d8d03af567b4d018f4d981cc156ec95 P d3658f55a8284d068408ccb41c0e67f5: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/6d8d03af567b4d018f4d981cc156ec95/wal-000000033 (ops 159-163)
I20260812 06:20:31.783037  6246 log.cc:1079] T 6d8d03af567b4d018f4d981cc156ec95 P d3658f55a8284d068408ccb41c0e67f5: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/6d8d03af567b4d018f4d981cc156ec95/wal-000000034 (ops 164-168)
I20260812 06:20:31.783077  6246 log.cc:1079] T 6d8d03af567b4d018f4d981cc156ec95 P d3658f55a8284d068408ccb41c0e67f5: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/6d8d03af567b4d018f4d981cc156ec95/wal-000000035 (ops 169-173)
I20260812 06:20:31.783114  6246 log.cc:1079] T 6d8d03af567b4d018f4d981cc156ec95 P d3658f55a8284d068408ccb41c0e67f5: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/6d8d03af567b4d018f4d981cc156ec95/wal-000000036 (ops 174-178)
I20260812 06:20:31.783155  6246 log.cc:1079] T 6d8d03af567b4d018f4d981cc156ec95 P d3658f55a8284d068408ccb41c0e67f5: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/6d8d03af567b4d018f4d981cc156ec95/wal-000000037 (ops 179-183)
I20260812 06:20:31.783196  6246 log.cc:1079] T 6d8d03af567b4d018f4d981cc156ec95 P d3658f55a8284d068408ccb41c0e67f5: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/6d8d03af567b4d018f4d981cc156ec95/wal-000000038 (ops 184-188)
I20260812 06:20:31.783233  6246 log.cc:1079] T 6d8d03af567b4d018f4d981cc156ec95 P d3658f55a8284d068408ccb41c0e67f5: Deleting log segment in path: /tmp/dist-test-taskBGm0hj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621131617-5928-0/minicluster-data/ts-0-root/wals/6d8d03af567b4d018f4d981cc156ec95/wal-000000039 (ops 189-193)
I20260812 06:20:31.815443  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: LogGCOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.033s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:20:31.815843  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling UndoDeltaBlockGCOp(6d8d03af567b4d018f4d981cc156ec95): 492 bytes on disk
I20260812 06:20:31.816370  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: UndoDeltaBlockGCOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4}
I20260812 06:20:31.817077  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95): perf score=3.181125
I20260812 06:20:31.829159  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.012s	user 0.008s	sys 0.003s Metrics: {"bytes_written":4676998,"delete_count":0,"lbm_write_time_us":4683,"lbm_writes_lt_1ms":117,"reinsert_count":0,"update_count":570}
I20260812 06:20:31.829658  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95): perf score=2.188937
I20260812 06:20:31.839272  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: FlushDeltaMemStoresOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.009s	user 0.004s	sys 0.003s Metrics: {"bytes_written":3528305,"delete_count":0,"lbm_write_time_us":3539,"lbm_writes_lt_1ms":89,"reinsert_count":0,"update_count":430}
I20260812 06:20:31.839953  6317 maintenance_manager.cc:419] P d3658f55a8284d068408ccb41c0e67f5: Scheduling MajorDeltaCompactionOp(6d8d03af567b4d018f4d981cc156ec95): perf score=1.000000
I20260812 06:20:31.940110  5928 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.091s	user 1.906s	sys 0.165s
I20260812 06:20:32.039196  5928 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.099s	user 0.001s	sys 0.000s
I20260812 06:20:32.039832  5928 tablet_server.cc:179] TabletServer@127.5.202.1:0 shutting down...
I20260812 06:20:32.055406  6246 maintenance_manager.cc:643] P d3658f55a8284d068408ccb41c0e67f5: MajorDeltaCompactionOp(6d8d03af567b4d018f4d981cc156ec95) complete. Timing: real 0.215s	user 0.147s	sys 0.068s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979733,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":501,"lbm_read_time_us":16148,"lbm_reads_lt_1ms":770,"lbm_write_time_us":34262,"lbm_writes_lt_1ms":743,"mutex_wait_us":18,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":14976,"thread_start_us":77,"threads_started":1,"update_count":3500}
I20260812 06:20:32.056488  5928 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:20:32.056943  5928 tablet_replica.cc:333] T 6d8d03af567b4d018f4d981cc156ec95 P d3658f55a8284d068408ccb41c0e67f5: stopping tablet replica
I20260812 06:20:32.057119  5928 raft_consensus.cc:2243] T 6d8d03af567b4d018f4d981cc156ec95 P d3658f55a8284d068408ccb41c0e67f5 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:32.057301  5928 raft_consensus.cc:2272] T 6d8d03af567b4d018f4d981cc156ec95 P d3658f55a8284d068408ccb41c0e67f5 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:32.072539  5928 tablet_server.cc:196] TabletServer@127.5.202.1:0 shutdown complete.
I20260812 06:20:32.114389  5928 master.cc:562] Master@127.5.202.62:39105 shutting down...
I20260812 06:20:32.118306  5928 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 74420c6141ad40a49284a9a8423ae08f [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:32.118526  5928 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 74420c6141ad40a49284a9a8423ae08f [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:32.118621  5928 tablet_replica.cc:333] T 00000000000000000000000000000000 P 74420c6141ad40a49284a9a8423ae08f: stopping tablet replica
I20260812 06:20:32.131086  5928 master.cc:584] Master@127.5.202.62:39105 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5576 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11076 ms total)

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